Different machine, same pluto memory issue, likely culprit found
Paul Wouters <[email protected]> Wed, 3 Dec 2003 01:03:41 +0100 (MET)
| Newsgroups | gmane.network.freeswan.user,gmane.network.freeswan.devel |
|---|---|
| Message-ID | <[email protected]> |
On Mon, 1 Dec 2003, Paul Wouters wrote: (This email contains information regarding a few machines that accidently are causing problems with freeswan. Note that we do realise this is our bug, but are sending you this information as it involves some badly setup DNS) > > If you are willing to recompile pluto, there is a compile-time macro > > to select malloc debugging. See "LEAK_DETECTIVE" in > > freeswan/programs/pluto/Makefile. I just had the same pluto problem on the machine next to it. 40% memory. dmesg showed lots of: Out of Memory: Killed process 14212 (mj_queuerun). Out of Memory: Killed process 14223 (mj_queuerun). sending pkt_too_big (len[1500] pmtu[1443]) to self sending pkt_too_big (len[1500] pmtu[1443]) to self hw tcp v4 csum failed hw tcp v4 csum failed sending pkt_too_big (len[1500] pmtu[1443]) to self Out of Memory: Killed process 14640 (mj_queuerun). sending pkt_too_big (len[1500] pmtu[1443]) to self hw tcp v4 csum failed hw tcp v4 csum failed hw tcp v4 csum failed sending pkt_too_big (len[1500] pmtu[1443]) to self Out of Memory: Killed process 14296 (mj_queuerun). sending pkt_too_big (len[1500] pmtu[1443]) to self sending pkt_too_big (len[1500] pmtu[1443]) to self hw tcp v4 csum failed hw tcp v4 csum failed sending pkt_too_big (len[1500] pmtu[1443]) to self This was freeswan 2.02-pre1 > > If you can repeat the experiment with 2.02, it might be help to > > determine if the problem was introduced between 2.02 and 2.03. So it seems this has been a problem before the 2.02-> 2.03 change. I find a truckload of these in the last couple of days at least with the identical IP: Nov 30 04:34:39 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[4652] ...66.134.99.194===66.134.99.202/32 #10828: starting keying attempt 2 of at most 3 Nov 30 04:34:39 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[4652] ...66.134.99.194===66.134.99.202/32 #10829: initiating Main Mode to replace #10828 Nov 30 04:34:39 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[4652] ...66.134.99.194===66.134.99.202/32 #10829: ERROR: asynchronous network error report on eth0 for message to 66.134.99.194 port 500, complainant 66.134.99.194: Connection refused [errno 111, origin ICMP type 3 code 3 (not authenticated)] Nov 30 04:34:49 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[4652] ...66.134.99.194===66.134.99.202/32 #10829: ERROR: asynchronous network error report on eth0 for message to 66.134.99.194 port 500, complainant 66.134.99.194: Connection refused [errno 111, origin ICMP type 3 code 3 (not authenticated)] Ofcourse, the DNS admin for this box should probably be shot once for every CNAME pointing to another CNAME 194.99.134.66.in-addr.arpa is an alias for h-66-134-99-194.sylvan-glade.com. 202.99.134.66.in-addr.arpa is an alias for h-66-134-99-202.sylvan-glade.com. h-66-134-99-194.sylvan-glade.com is an alias for 194.99.134.66.in-addr.sylvan-glade.com. 194.99.134.66.in-addr.sylvan-glade.com domain name pointer gw01.sylvan-glade.com. gw01.sylvan-glade.com has key 16896 4 1 AQNyN7bmlaGYwOC/3rhEkS602jQKfMYPeDx4GLzKHFQmiMSOvXrW34NU Ns4e4VdbKpk/rO5AkY1nAKhCEqL/mxvUdYxU+bR/V4L6Y4dcUARQ+p0S XuN0llk+dvfhsbZvu7vIbWdt05Y4a8s/NG+TsB61tpDIrF2mXPuke86y 6DdWGE8ff1JgpLDF83/Ojy/hXIiQcH8bI8vHNNBQ7EVoDaAbp+SDQpjL pTSs8oXN19+fCMHBNuBTAyvjZ2lspA17IdA7f7tQrebVQ/c7UTOSDMxO 3KbLmyw9quAeTO/8D63nxe2FUWbGZxLwkxHSkfDdgAvHszn+VCBEXsYA QTsQ0jJv gw01.sylvan-glade.com has address 66.134.99.194 194.99.134.66.in-addr.arpa is an alias for h-66-134-99-194.sylvan-glade.com. This is where we loop back to the start. Some other pieces of log near an error: Dec 2 17:54:15 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5336] ...212.62.197.94 #12401: initiating Main Mode to replace #12398 Dec 2 17:54:48 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5337] ...193.110.157.76===193.110.157.5/32 #12402: responding to Quick Mode Dec 2 17:54:54 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5337] ...193.110.157.76===193.110.157.5/32 #12402: IPsec SA established Dec 2 17:55:26 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5336] ...212.62.197.94 #12401: max number of retransmissions (2) reached STATE_MAIN_I1. No response (or no acceptable response) to our first IKE message Dec 2 17:55:26 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5336] ...212.62.197.94: deleting connection "private-or-clear#0.0.0.0/0" instance with peer 212.62.197.94Dec 2 17:59:15 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5337] ...193.110.157.76===193.110.157.5/32 #12399: received Delete SA payload: deleting IPSEC State #12400 Dec 2 17:59:50 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5337] ...193.110.157.76===193.110.157.5/32 #12399: received Delete SA payload: deleting IPSEC State #12402 Dec 2 18:06:55 nso pluto[8097]: "packetdefault"[281] 0.0.0.0/0=== ...192.139.46.135===? #12403: responding to Main Mode from unknown peer 192.139.46.135 Dec 2 18:07:00 nso pluto[8097]: "packetdefault"[281] 0.0.0.0/0=== ...192.139.46.135===? #12404: responding to Main Mode from unknown peer 192.139.46.135 Dec 2 18:07:19 nso pluto[8097]: "packetdefault"[281] 0.0.0.0/0=== ...192.139.46.135===? #12403: sent MR3, ISAKMP SA established Dec 2 18:07:19 nso pluto[8097]: "packetdefault"[281] 0.0.0.0/0=== ...192.139.46.135===? #12403: retransmitting in response to duplicate packet; already STATE_MAIN_R3 Dec 2 18:07:33 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5338] ...192.139.46.135===192.139.46.76/32 #12405: responding to Quick Mode Dec 2 18:07:36 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5338] ...192.139.46.135===192.139.46.76/32 #12405: discarding duplicate packet; already STATE_QUICK_R1 Dec 2 18:07:38 nso pluto[8097]: ERROR: "private-or-clear#0.0.0.0/0"[5338] ...192.139.46.135===192.139.46.76/32 #12405: pfkey write() of SADB_X_ADDFLOW message 1391398 for flow [email protected] failed. Errno 17: File exists Dec 2 18:07:38 nso pluto[8097]: | 02 0e 00 09 17 00 00 00 26 3b 15 00 a1 1f 00 00 Dec 2 18:07:38 nso pluto[8097]: | 03 00 01 00 00 00 21 d1 00 00 00 00 00 00 00 00 Dec 2 18:07:39 nso pluto[8097]: | ff ff ff ff 00 00 00 00 03 00 05 00 00 00 00 00 Dec 2 18:07:39 nso pluto[8097]: | 02 00 00 00 c1 6e 9d 59 00 00 00 00 00 00 00 00 Dec 2 18:07:39 nso pluto[8097]: | 03 00 06 00 00 00 00 00 02 00 01 f4 c0 8b 2e 87 Dec 2 18:07:40 nso pluto[8097]: | 00 00 00 00 00 00 00 00 03 00 15 00 00 00 00 00 Dec 2 18:07:40 nso pluto[8097]: | 02 00 00 00 c1 6e 9d 59 00 00 00 00 00 00 00 00 Dec 2 18:07:40 nso pluto[8097]: | 03 00 16 00 00 00 00 00 02 00 00 00 c0 8b 2e 4c Dec 2 18:07:41 nso pluto[8097]: | 4b da ff db 96 36 f0 62 03 00 17 00 00 00 00 00 Dec 2 18:07:41 nso pluto[8097]: | 02 00 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 Dec 2 18:07:41 nso pluto[8097]: | 03 00 18 00 00 00 00 00 02 00 00 00 ff ff ff ff Dec 2 18:07:42 nso pluto[8097]: | e0 f6 ff bf e0 f6 ff bf Dec 2 18:07:43 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5338] ...192.139.46.135===192.139.46.76/32 #12406: initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+DONTREKEY+OPPORTUNISTIC+failurePASS Dec 2 18:07:54 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5338] ...192.139.46.135===192.139.46.76/32 #12406: sent QI2, IPsec SA established Dec 2 18:07:56 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5338] ...192.139.46.135===192.139.46.76/32 #12405: IPsec SA established Dec 2 18:08:09 nso sshd[11681]: Accepted publickey for abidump from 192.139.46.76 port 41142 ssh2 I also see this earlier in the logs: Dec 2 17:19:05 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5335] ...212.62.197.94: deleting connection "private-or-clear#0.0.0.0/0" instance with peer 212.62.197.94 Dec 2 17:20:44 nso pluto[8097]: INTERNAL ERROR: /proc/net/ipsec_eroute line 1343 source subnet field malformed: byte overflow in dotted-decimal address Dec 2 17:20:47 nso pluto[8097]: ERROR: pfkey write() of SADB_X_DELFLOW message 1386708 for flow %pass failed. Errno 14: Bad address Dec 2 17:20:47 nso pluto[8097]: | 02 0f 00 0b 0e 00 00 00 d4 28 15 00 a1 1f 00 00 Dec 2 17:20:47 nso pluto[8097]: | 03 00 15 00 00 00 00 00 02 00 00 00 c1 6e 9d 59 Dec 2 17:20:47 nso pluto[8097]: | 00 00 00 00 00 00 00 00 03 00 16 00 00 00 00 00 Dec 2 17:20:47 nso pluto[8097]: | 02 00 00 00 db 64 1f ef 00 00 00 00 00 00 00 00 Dec 2 17:20:47 nso pluto[8097]: | 03 00 17 00 00 00 00 00 02 00 00 00 ff ff ff ff Dec 2 17:20:48 nso pluto[8097]: | 4f 0f 0d 15 a0 79 17 40 03 00 18 00 00 00 00 00 Dec 2 17:20:48 nso pluto[8097]: | 02 00 00 00 ff ff ff ff d9 bb cc 3f 00 00 00 00 Dec 2 17:21:06 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5313] ...193.110.157.76===193.110.157.5/32 #12340: ISAKMP SA expired (--dontrekey) Dec 2 17:21:06 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[5313] ...193.110.157.76===193.110.157.5/32: deleting connection "private-or-clear#0.0.0.0/0" instance with peer 193.110.157.76 And Nov 30 16:03:46 nso pluto[8097]: INTERNAL ERROR: /proc/net/ipsec_eroute line 940 source subnet field malformed: byte overflow in dotted-decimal address And Nov 30 15:48:24 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[4754] ...66.134.99.194===66.134.99.201/32 #11030: ERROR: asynchronous network error report on eth0 for message to 66.134.99.194 port 500, complainant 66.134.99.194: Connection refused [errno 111, origin ICMP type 3 code 3 (not authenticated)] Nov 30 15:49:03 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[4754] ...66.134.99.194===66.134.99.201/32 #11030: max number of retransmissions (2) reached STATE_MAIN_I1. No response (or no acceptable response) to our first IKE message Nov 30 15:49:03 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[4754] ...66.134.99.194===66.134.99.201/32: deleting connection "private-or-clear#0.0.0.0/0" instance with peer 66.134.99.194 Nov 30 15:49:45 nso pluto[8097]: ERROR: pfkey write() of SADB_X_DELFLOW message 1214757 for flow %pass failed. Errno 14: Bad address Nov 30 15:49:45 nso pluto[8097]: | 02 0f 00 0b 0e 00 00 00 25 89 12 00 a1 1f 00 00 Nov 30 15:49:45 nso pluto[8097]: | 03 00 15 00 00 00 00 00 02 00 00 00 c1 6e 9d 59 Nov 30 15:49:45 nso pluto[8097]: | 00 00 00 00 00 00 00 00 03 00 16 00 00 00 00 00 Nov 30 15:49:45 nso pluto[8097]: | 02 00 00 00 d9 ef 18 4c 00 00 00 00 00 00 00 00 Nov 30 15:49:45 nso pluto[8097]: | 03 00 17 00 00 00 00 00 02 00 00 00 ff ff ff ff Nov 30 15:49:45 nso pluto[8097]: | 4f 0f 0d 15 a0 79 17 40 03 00 18 00 00 00 00 00 Nov 30 15:49:45 nso pluto[8097]: | 02 00 00 00 ff ff ff ff 89 03 ca 3f 00 00 00 00 Nov 30 15:50:43 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[4755] ...216.126.78.97 #11031: initiating Main Mode Nov 30 15:50:46 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[4755] ...216.126.78.97 #11031: ISAKMP SA established Nov 30 15:50:46 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[4755] ...216.126.78.97 #11032: initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+DONTREKEY+OPPORTUNISTIC+failurePASS Nov 30 15:50:46 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[4755] ...216.126.78.97 #11032: sent QI2, IPsec SA established Nov 30 15:50:47 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[4755] ...216.126.78.97 #11033: responding to Quick Mode Nov 30 15:50:47 nso pluto[8097]: "private-or-clear#0.0.0.0/0"[4755] ...216.126.78.97 #11033: IPsec SA established ExecSum: 1) sysadmin making looping CNAMEs (even killing SOA records, tsk tsk) 2) Bug with pluto perhaps following looping cnames eating up more and more memory? 3) bug with pluto reading/writing eroute's (perhaps due to 2) and machine overload/excessive memory usage) At the moment of writing, there are only 186 eroutes, but this might vary on the amount of emails this machine sends. (It's the freeswan list server :) Paul ps. If the person at sylvan-glade.com needs some help or would like to talk about DNS and OE issues, feel free to contact me. It's nice to see people putting in IPsec keys in DNS (even if RFC2535 obsoletes those :) pps. Since this is happening on our webserver and our listserver, we know the culprit is subscribed to one of our lists