Dear folks,
I have a problem with an IPSec tunnel where after any amount of time (sometimes 20 mins, sometimes hours or days), traffic will just stop flowing even though the tunnel is up. One side will show multiple SAD entries.
If I start deleting "unused" SADs, the tunnel will start working again. Obviously that isn't a solution.
Here are some facts:
- Both sides running on 2.0.1-RELEASE (amd64) built on Mon Dec 12 18:43:51 EST 2011
- Both sides have "Prefer older SAs" in the advanced settings disabled (it used to be enabled but made no difference).
- DPD is enabled and I tried playing with the values as well as disabling it completely
- With DPD disabled, the tunnel stays stalled longer
Log file from main side:
Apr 11 21:08:42 racoon: [SRVNAME1]: [192.168.4.170] ERROR: unknown Informational exchange received.
Apr 11 21:08:37 racoon: [SRVNAME1]: [192.168.4.170] ERROR: unknown Informational exchange received.
Apr 11 21:08:32 racoon: [SRVNAME1]: [192.168.4.170] ERROR: unknown Informational exchange received.
Apr 11 21:08:27 racoon: [SRVNAME1]: [192.168.4.170] ERROR: unknown Informational exchange received.
Apr 11 21:08:22 racoon: [SRVNAME1]: [192.168.4.170] ERROR: unknown Informational exchange received.
Apr 11 21:08:17 racoon: [SRVNAME1]: [192.168.4.170] ERROR: unknown Informational exchange received.
Apr 11 21:08:09 racoon: [SRVNAME1]: INFO: ISAKMP-SA deleted 192.168.4.161[500]-192.168.4.170[500] spi:46e62d437290ff7b:5cc826162841f6bd
Apr 11 21:08:09 racoon: [SRVNAME1]: INFO: ISAKMP-SA expired 192.168.4.161[500]-192.168.4.170[500] spi:46e62d437290ff7b:5cc826162841f6bd
Apr 11 20:44:09 racoon: [SRVNAME1]: INFO: ISAKMP-SA established 192.168.4.161[500]-192.168.4.170[500] spi:925fc1a1ea707663:82dd5b1ab2aae2a1
Apr 11 20:44:09 racoon: INFO: received broken Microsoft ID: FRAGMENTATION
Apr 11 20:44:09 racoon: INFO: received Vendor ID: DPD
Apr 11 20:44:09 racoon: INFO: begin Identity Protection mode.
Apr 11 20:44:09 racoon: [SRVNAME1]: INFO: initiate new phase 1 negotiation: 192.168.4.161[500]<=>192.168.4.170[500]
Apr 11 20:44:09 racoon: [SRVNAME1]: INFO: renegotiating phase1 to 192.168.4.170 due to active phase2
Apr 11 19:08:10 racoon: [SRVNAME1]: INFO: IPsec-SA established: ESP 192.168.4.161[500]->192.168.4.170[500] spi=177262234(0xa90ce9a)
Apr 11 19:08:10 racoon: [SRVNAME1]: INFO: IPsec-SA established: ESP 192.168.4.161[500]->192.168.4.170[500] spi=16163632(0xf6a330)
Apr 11 19:08:10 racoon: [SRVNAME1]: INFO: initiate new phase 2 negotiation: 192.168.4.161[500]<=>192.168.4.170[500]
Apr 11 19:08:09 racoon: [SRVNAME1]: [192.168.4.170] INFO: received INITIAL-CONTACT
Apr 11 19:08:09 racoon: [SRVNAME1]: INFO: ISAKMP-SA established 192.168.4.161[500]-192.168.4.170[500] spi:46e62d437290ff7b:5cc826162841f6bd
Apr 11 19:08:09 racoon: INFO: received broken Microsoft ID: FRAGMENTATION
Apr 11 19:08:09 racoon: INFO: received Vendor ID: DPD
Apr 11 19:08:09 racoon: INFO: begin Identity Protection mode.
Apr 11 19:08:09 racoon: [SRVNAME1]: INFO: initiate new phase 1 negotiation: 192.168.4.161[500]<=>192.168.4.170[500]
Apr 11 19:08:09 racoon: [SRVNAME1]: INFO: IPsec-SA request for 192.168.4.170 queued due to no phase1 found.
Apr 11 19:08:06 racoon: ERROR: such policy already exists. anyway replace it: 192.168.5.176/28[0] 192.168.0.0/16[0] proto=any dir=in
Apr 11 19:08:06 racoon: ERROR: such policy already exists. anyway replace it: 192.168.0.0/16[0] 192.168.5.176/28[0] proto=any dir=out
Apr 11 19:08:06 racoon: ERROR: such policy already exists. anyway replace it: 192.168.4.0/27[0] 192.168.4.11/32[0] proto=any dir=in
Apr 11 19:08:06 racoon: ERROR: such policy already exists. anyway replace it: 192.168.4.11/32[0] 192.168.4.0/27[0] proto=any dir=out
Apr 11 19:08:06 racoon: INFO: unsupported PF_KEY message REGISTER
Apr 11 19:08:06 racoon: [Self]: INFO: 192.168.4.161[500] used as isakmp port (fd=15)
Apr 11 19:08:06 racoon: [Self]: INFO: 192.168.4.161[500] used for NAT-T
Apr 11 19:08:06 racoon: [Self]: INFO: 192.168.4.161[4500] used as isakmp port (fd=14)
Apr 11 19:08:06 racoon: [Self]: INFO: 192.168.4.161[4500] used for NAT-T
Apr 11 19:08:06 racoon: INFO: Reading configuration from "/var/etc/racoon.conf"
Apr 11 19:08:06 racoon: INFO: @(#)This product linked OpenSSL 0.9.8n 24 Mar 2010 (http://www.openssl.org/)
Apr 11 19:08:06 racoon: INFO: @(#)ipsec-tools 0.8.0 (http://ipsec-tools.sourceforge.net)
Main site config:
# This file is automatically generated. Do not edit
path pre_shared_key "/var/etc/psk.txt";
path certificate "/var/etc";
listen
{
adminsock "/var/db/racoon/racoon.sock" "root" "wheel" 0660;
isakmp 192.168.4.161 [500];
isakmp_natt 192.168.4.161 [4500];
}
remote 192.168.4.170
{
ph1id 1;
exchange_mode main;
my_identifier address 192.168.4.161;
peers_identifier address 192.168.4.170;
ike_frag on;
generate_policy = off;
initial_contact = on;
nat_traversal = off;
dpd_delay = 10;
dpd_maxfail = 30;
support_proxy on;
proposal_check claim;
proposal
{
authentication_method pre_shared_key;
encryption_algorithm blowfish 128;
hash_algorithm sha1;
dh_group 2;
lifetime time 7200 secs;
}
}
sainfo subnet 192.168.0.0/16 any subnet 192.168.5.176/28 any
{
remoteid 1;
encryption_algorithm aes 128;
authentication_algorithm hmac_sha1;
lifetime time 14400 secs;
compression_algorithm deflate;
}
Log file from remote side:
Apr 11 21:09:30 racoon: [REMOTESRV]: INFO: ISAKMP-SA deleted 192.168.4.170[500]-192.168.4.161[47456] spi:46e62d437290ff7b:5cc826162841f6bd
Apr 11 21:09:30 racoon: [REMOTESRV]: INFO: ISAKMP-SA expired 192.168.4.170[500]-192.168.4.161[47456] spi:46e62d437290ff7b:5cc826162841f6bd
Apr 11 20:45:02 racoon: [REMOTESRV]: INFO: ISAKMP-SA established 192.168.4.170[500]-192.168.4.161[47456] spi:925fc1a1ea707663:82dd5b1ab2aae2a1
Apr 11 20:45:02 racoon: INFO: received Vendor ID: DPD
Apr 11 20:45:02 racoon: INFO: received broken Microsoft ID: FRAGMENTATION
Apr 11 20:45:02 racoon: INFO: begin Identity Protection mode.
Apr 11 20:45:02 racoon: [REMOTESRV]: INFO: respond new phase 1 negotiation: 192.168.4.170[500]<=>192.168.4.161[47456]
Apr 11 19:09:31 racoon: [REMOTESRV]: INFO: IPsec-SA established: ESP 192.168.4.170[500]->192.168.4.161[500] spi=16163632(0xf6a330)
Apr 11 19:09:31 racoon: [REMOTESRV]: INFO: IPsec-SA established: ESP 192.168.4.170[500]->192.168.4.161[500] spi=177262234(0xa90ce9a)
Apr 11 19:09:31 racoon: [REMOTESRV]: INFO: respond new phase 2 negotiation: 192.168.4.170[500]<=>192.168.4.161[47456]
Apr 11 19:09:30 racoon: [REMOTESRV]: [192.168.4.161] INFO: received INITIAL-CONTACT
Apr 11 19:09:30 racoon: [REMOTESRV]: INFO: ISAKMP-SA established 192.168.4.170[500]-192.168.4.161[47456] spi:46e62d437290ff7b:5cc826162841f6bd
Apr 11 19:09:30 racoon: INFO: received Vendor ID: DPD
Apr 11 19:09:30 racoon: INFO: received broken Microsoft ID: FRAGMENTATION
Apr 11 19:09:30 racoon: INFO: begin Identity Protection mode.
Apr 11 19:09:30 racoon: [REMOTESRV]: INFO: respond new phase 1 negotiation: 192.168.4.170[500]<=>192.168.4.161[47456]
Apr 11 19:09:23 racoon: [REMOTESRV]: INFO: ISAKMP-SA deleted 192.168.4.170[500]-192.168.4.161[19023] spi:570fe0f8e55158b9:4fc91de568468927
Apr 11 19:09:23 racoon: INFO: purged ISAKMP-SA spi=570fe0f8e55158b9:4fc91de568468927.
Apr 11 19:09:23 racoon: INFO: purging ISAKMP-SA spi=570fe0f8e55158b9:4fc91de568468927.
Apr 11 19:09:23 racoon: [REMOTESRV]: [192.168.4.161] WARNING: remote address mismatched. db=192.168.4.161[19023], act=192.168.4.161[47456]
Apr 11 19:09:22 racoon: ERROR: 192.168.4.161 give up to get IPsec-SA due to time up to wait.
Apr 11 19:08:55 racoon: NOTIFY: the packet is retransmitted by 192.168.4.161[47456] (2).
Apr 11 19:08:52 racoon: [REMOTESRV]: INFO: initiate new phase 2 negotiation: 192.168.4.170[500]<=>192.168.4.161[19023]
Apr 11 19:08:45 racoon: NOTIFY: the packet is retransmitted by 192.168.4.161[47456] (2).
Apr 11 19:08:40 racoon: INFO: unsupported PF_KEY message REGISTER
Apr 11 19:08:39 racoon: ERROR: pfkey DELETE received: ESP 192.168.4.161[500]->192.168.4.170[500] spi=248157879(0xeca96b7)
Apr 11 19:08:39 racoon: ERROR: pfkey DELETE received: ESP 192.168.4.161[500]->192.168.4.170[500] spi=262712372(0xfa8ac34)
Apr 11 19:08:39 racoon: INFO: unsupported PF_KEY message REGISTER
Remote side config:
# This file is automatically generated. Do not edit
path pre_shared_key "/var/etc/psk.txt";
path certificate "/var/etc";
listen
{
adminsock "/var/db/racoon/racoon.sock" "root" "wheel" 0660;
isakmp 192.168.4.170 [500];
isakmp_natt 192.168.4.170 [4500];
}
remote 192.168.4.161
{
ph1id 1;
exchange_mode main;
my_identifier address 192.168.4.170;
peers_identifier address 192.168.4.161;
ike_frag on;
generate_policy = off;
initial_contact = on;
nat_traversal = off;
dpd_delay = 10;
dpd_maxfail = 30;
support_proxy on;
proposal_check claim;
proposal
{
authentication_method pre_shared_key;
encryption_algorithm blowfish 128;
hash_algorithm sha1;
dh_group 2;
lifetime time 7200 secs;
}
}
sainfo subnet 192.168.5.176/28 any subnet 192.168.0.0/16 any
{
remoteid 1;
encryption_algorithm aes 128;
authentication_algorithm hmac_sha1;
lifetime time 14400 secs;
compression_algorithm deflate;
}
The only posts I could find were related to mismatched settings, but they all seem to agree.
Does anyone have any idea? It seems like other people have this working.