[Swan] Pluto consumes all available memory
Will Roberts
ironwill42 at gmail.com
Wed May 20 22:20:00 EEST 2015
On 05/20/2015 03:08 PM, Paul Wouters wrote:
>
>> The error was triggered again, but unfortunately the leak detector
>> still shows the same exact leaks.
>
> Which were? there must have been a lot of the,?
These are the exact same leaks in the exact same quantity from my
original report, nothing is building up over time and being detected.
May 20 18:01:57 sanfrancisco pluto[7864]: leak: 4 * struct event in
event_schedule(), item size: 32
May 20 18:01:57 sanfrancisco pluto[7864]: leak: pluto crypto helpers,
item size: 64
May 20 18:01:57 sanfrancisco pluto[7864]: leak detective found 5 leaks,
total size 96
>
>> The following errors were printed during the shutdown process:
>>
>> May 20 18:01:57 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
>> 69.90.78.100: deleting connection "wonderproxy-L2TP" instance with
>> peer 69.90.78.100 {isakmp=#0/ipsec=#0}
>> May 20 18:01:57 sanfrancisco pluto[7864]: "wonderproxy-L2TP" #34623:
>> deleting state (STATE_QUICK_R1)
>
> You had 34623 states since startup. Usually that indicates tunnels that
> are infinitely failing to establish. I suspect something in the error
> path is leaking that memory.
Our monitoring system repeatedly sets up and tears down tunnels; its
purpose is to verify that the system is able to accept incoming requests
and properly create the tunnel. This process happens every 5 minutes,
from each of our 3 monitoring systems. So that is 864 tunnels a day, and
with 2 states used per tunnel, 34623 is roughly 20 days worth of testing
tunnels.
>
>> May 20 18:01:57 sanfrancisco pluto[7864]: "wonderproxy-L2TP" #34623:
>> ERROR: netlink response for Del SA esp.b7f1c7e7 at 198.199.98.122
>> included errno 3: No such process
>
> Those are SA's the kernel deleted but pluto thought those should still
> be there. I'm confused what would have happened to those.
These are ones that were detected as failures by our monitoring system.
Here is the full log for #34622/34623:
May 20 17:49:13 sanfrancisco pluto[7864]: packet from 69.90.78.100:500:
received Vendor ID payload [Dead Peer Detection]
May 20 17:49:13 sanfrancisco pluto[7864]: packet from 69.90.78.100:500:
received Vendor ID payload [FRAGMENTATION]
May 20 17:49:13 sanfrancisco pluto[7864]: packet from 69.90.78.100:500:
received Vendor ID payload [RFC 3947]
May 20 17:49:13 sanfrancisco pluto[7864]: packet from 69.90.78.100:500:
ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03]
May 20 17:49:13 sanfrancisco pluto[7864]: packet from 69.90.78.100:500:
ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n]
May 20 17:49:13 sanfrancisco pluto[7864]: packet from 69.90.78.100:500:
ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02]
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34622: enabling possible NAT-traversal with method RFC
3947 (NAT-Traversal)
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34622: responding to Main Mode from unknown peer 69.90.78.100
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34622: transition from state STATE_MAIN_R0 to state
STATE_MAIN_R1
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34622: STATE_MAIN_R1: sent MR1, expecting MI2
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34622: NAT-Traversal: Result using RFC 3947
(NAT-Traversal) sender port 500: no NA
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34622: transition from state STATE_MAIN_R1 to state
STATE_MAIN_R2
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34622: STATE_MAIN_R2: sent MR2, expecting MI3
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34622: Main mode peer ID is ID_IPV4_ADDR: '69.90.78.100'
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34622: transition from state STATE_MAIN_R2 to state
STATE_MAIN_R3
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34622: STATE_MAIN_R3: sent MR3, ISAKMP SA established
{auth=PRESHARED_KEY cipher=a
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34622: the peer proposed: 198.199.98.122/32:17/1701 ->
69.90.78.100/32:17/1701
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34623: responding to Quick Mode proposal {msgid:0fc8804b}
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34623: us: 198.199.98.122<198.199.98.122>:17/1701
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34623: them: 69.90.78.100:17/1701
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34623: transition from state STATE_QUICK_R0 to state
STATE_QUICK_R1
May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34623: STATE_QUICK_R1: sent QR1, inbound IPsec SA
installed, expecting QI2
*May 20 17:49:13 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34623: unable to popen up-host command*
May 20 17:49:23 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34623: discarding duplicate packet; already STATE_QUICK_R1
May 20 17:49:33 sanfrancisco pluto[7864]: "wonderproxy-L2TP"[15046]
69.90.78.100 #34623: discarding duplicate packet; already STATE_QUICK_R1
>
>> 198.199.98.122 - is that machine's local IP
>> 69.90.78.100, 176.58.89.113, and 198.58.96.25 are the IPs of our
>> monitoring servers
>
> If this is just 1-3 machines, then you must see a continuous log of IKE
> failures?
No, I don't see any failures/errors in the log until this issue is
triggered.
--Will
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20150520/6e2e500a/attachment.html>
More information about the Swan
mailing list