[Openswan dev] Possible Memory Leak in Openswan 2.4.5

[Jim Barber]

Hi Openswan developers.

I am running the Debian packaged version of Openswan on one of our servers here at work.
The Debian Package version is openswan 2.4.5+dfsg-0.2.

I have about 6 IPSec tunnels defined to remote sites.
One of the tunnels was working but then I mis-configured it so that the two ends didn't agree with each other.
Originally the local network was set up to be 10.128.0.0/22 but upon expanding, I changed it to 10.128.0.0/16
However I stuffed up and didn't change it at the other end for one of the tunnels, and so that tunnel no longer worked.

What would happen is that Phase 1 of the IPSec tunnel did the shared key exchange and successfully completed.
The phase 2 part failed with an error about INVALID_ID_INFORMATION due to the mismatched 10.128.0.0/22 vs 10.128.0.0/16.

Anyway, the problem was that I didn't fix it as that particular tunnel was just for testing (hence why I missed it) and I was snowed under with other work.
With a mis-configuration like this, after a while the pluto process starts to take up a huge amount of memory.
What happens is that it doesn't seem to leak for about a week and a half, then all of a sudden it starts rapidly consuming memory.

The system has 1 Gigabyte of RAM which for the most part is unallocated (the box has firewall and some monitoring duties).
On a Thursday, the memory usage started to grow until the kernel's out of memory killer was invoked on a Sunday evening.
It killed a MySQL process instead of the pluto one, but when I investigated I could see that the pluto process was using up around 600MB of RAM.
On stopping and starting it, it shrank back to a reasonable size again.

I kept an eye on it, and after a week and a bit, sure enough the memory usage started to rise again.
Once it fell to halfway I fixed the configuration mismatch and did a 'ipsec auto --replace' command for the bad tunnel and then bought it up.
At that point memory usage stopped growing and has remained the same.
I haven't restarted the tunnels yet to regain the memory back as I don't need to yet.
It's been going for a number of days without freeing up what memory it's already taken, or trying to hog more again.

It is currently running on a 2.6.17.1 kernel using the NETKEY IPSec implementation.

Sorry for the long winded explanation.
But it seems a looping Phase 2 retry on a mismatched tunnel behaves for quite a while before something goes awry and it starts eating memory.
It's going to be hard to track down given my poor description I know...

In the logs you can see messages such as 'starting keying attempt $X of an unlimited number' where $X is a number.
These generally grow, but there seems to be a few sets of them growing... it's hard to explain.
Anyway, the biggest number I saw $X get up to was 9661 and was during the time of the problem.
It may be unrelated but I thought I'd mention it.

A sample of the errors in the logs for the badly configured connection follows.
These basically just repeat for days:

Jul 28 13:59:36 mail pluto[32625]: "phc-lan" #149374: max number of retransmissions (2) reached STATE_QUICK_I1.  No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
Jul 28 13:59:36 mail pluto[32625]: "phc-lan" #149374: starting keying attempt 3 of an unlimited number
Jul 28 13:59:36 mail pluto[32625]: "phc-lan" #149503: initiating Quick Mode PSK+ENCRYPT+COMPRESS+TUNNEL+PFS to replace #149374 {using isakmp#148729}
Jul 28 13:59:36 mail pluto[32625]: "phc-lan" #148729: ignoring informational payload, type INVALID_ID_INFORMATION
Jul 28 13:59:36 mail pluto[32625]: "phc-lan" #148729: received and ignored informational message
Jul 28 13:59:37 mail pluto[32625]: "phc-lan" #149375: max number of retransmissions (2) reached STATE_QUICK_I1.  No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
Jul 28 13:59:37 mail pluto[32625]: "phc-lan" #149375: starting keying attempt 124 of an unlimited number
Jul 28 13:59:37 mail pluto[32625]: "phc-lan" #149504: initiating Quick Mode PSK+ENCRYPT+COMPRESS+TUNNEL+PFS to replace #149375 {using isakmp#148729}
Jul 28 13:59:37 mail pluto[32625]: "phc-lan" #148729: ignoring informational payload, type INVALID_ID_INFORMATION
Jul 28 13:59:37 mail pluto[32625]: "phc-lan" #148729: received and ignored informational message
Jul 28 13:59:38 mail pluto[32625]: "phc-lan" #149377: max number of retransmissions (2) reached STATE_QUICK_I1.  No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
Jul 28 13:59:38 mail pluto[32625]: "phc-lan" #149377: starting keying attempt 194 of an unlimited number
Jul 28 13:59:38 mail pluto[32625]: "phc-lan" #149505: initiating Quick Mode PSK+ENCRYPT+COMPRESS+TUNNEL+PFS to replace #149377 {using isakmp#148729}
Jul 28 13:59:38 mail pluto[32625]: "phc-lan" #149376: max number of retransmissions (2) reached STATE_QUICK_I1.  No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
Jul 28 13:59:38 mail pluto[32625]: "phc-lan" #149376: starting keying attempt 8 of an unlimited number
Jul 28 13:59:38 mail pluto[32625]: "phc-lan" #149506: initiating Quick Mode PSK+ENCRYPT+COMPRESS+TUNNEL+PFS to replace #149376 {using isakmp#148729}
Jul 28 13:59:38 mail pluto[32625]: "phc-lan" #148729: ignoring informational payload, type INVALID_ID_INFORMATION
Jul 28 13:59:38 mail pluto[32625]: "phc-lan" #148729: received and ignored informational message
Jul 28 13:59:38 mail pluto[32625]: "phc-lan" #148729: ignoring informational payload, type INVALID_ID_INFORMATION
Jul 28 13:59:38 mail pluto[32625]: "phc-lan" #148729: received and ignored informational message
Jul 28 13:59:39 mail pluto[32625]: "phc-lan" #149379: max number of retransmissions (2) reached STATE_QUICK_I1.  No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
Jul 28 13:59:39 mail pluto[32625]: "phc-lan" #149379: starting keying attempt 159 of an unlimited number
Jul 28 13:59:39 mail pluto[32625]: "phc-lan" #149507: initiating Quick Mode PSK+ENCRYPT+COMPRESS+TUNNEL+PFS to replace #149379 {using isakmp#148729}
Jul 28 13:59:39 mail pluto[32625]: "phc-lan" #149378: max number of retransmissions (2) reached STATE_QUICK_I1.  No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
Jul 28 13:59:39 mail pluto[32625]: "phc-lan" #149378: starting keying attempt 57 of an unlimited number
Jul 28 13:59:39 mail pluto[32625]: "phc-lan" #149508: initiating Quick Mode PSK+ENCRYPT+COMPRESS+TUNNEL+PFS to replace #149378 {using isakmp#148729}
Jul 28 13:59:39 mail pluto[32625]: "phc-lan" #148729: ignoring informational payload, type INVALID_ID_INFORMATION
Jul 28 13:59:39 mail pluto[32625]: "phc-lan" #148729: received and ignored informational message
Jul 28 13:59:39 mail pluto[32625]: "phc-lan" #148729: ignoring informational payload, type INVALID_ID_INFORMATION
Jul 28 13:59:39 mail pluto[32625]: "phc-lan" #148729: received and ignored informational message
Jul 28 13:59:40 mail pluto[32625]: "phc-lan" #149380: max number of retransmissions (2) reached STATE_QUICK_I1.  No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
Jul 28 13:59:40 mail pluto[32625]: "phc-lan" #149380: starting keying attempt 229 of an unlimited number
Jul 28 13:59:40 mail pluto[32625]: "phc-lan" #149509: initiating Quick Mode PSK+ENCRYPT+COMPRESS+TUNNEL+PFS to replace #149380 {using isakmp#148729}
Jul 28 13:59:40 mail pluto[32625]: "phc-lan" #148729: ignoring informational payload, type INVALID_ID_INFORMATION
Jul 28 13:59:40 mail pluto[32625]: "phc-lan" #148729: received and ignored informational message
Jul 28 13:59:41 mail pluto[32625]: "phc-lan" #149382: max number of retransmissions (2) reached STATE_QUICK_I1.  No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
Jul 28 13:59:41 mail pluto[32625]: "phc-lan" #149382: starting keying attempt 22 of an unlimited number
Jul 28 13:59:41 mail pluto[32625]: "phc-lan" #149510: initiating Quick Mode PSK+ENCRYPT+COMPRESS+TUNNEL+PFS to replace #149382 {using isakmp#148729}
Jul 28 13:59:41 mail pluto[32625]: "phc-lan" #149381: max number of retransmissions (2) reached STATE_QUICK_I1.  No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
Jul 28 13:59:41 mail pluto[32625]: "phc-lan" #149381: starting keying attempt 92 of an unlimited number
Jul 28 13:59:41 mail pluto[32625]: "phc-lan" #149511: initiating Quick Mode PSK+ENCRYPT+COMPRESS+TUNNEL+PFS to replace #149381 {using isakmp#148729}
Jul 28 13:59:41 mail pluto[32625]: "phc-lan" #148729: ignoring informational payload, type INVALID_ID_INFORMATION
Jul 28 13:59:41 mail pluto[32625]: "phc-lan" #148729: received and ignored informational message
Jul 28 13:59:41 mail pluto[32625]: "phc-lan" #148729: ignoring informational payload, type INVALID_ID_INFORMATION
Jul 28 13:59:41 mail pluto[32625]: "phc-lan" #148729: received and ignored informational message

Regards,

-- 
----------
Jim Barber
DDI Health