From owner-freebsd-net@FreeBSD.ORG Tue Jul 5 11:28:49 2011 Return-Path: Delivered-To: freebsd-net@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 0AA63106566B; Tue, 5 Jul 2011 11:28:49 +0000 (UTC) (envelope-from egrosbein@rdtc.ru) Received: from eg.sd.rdtc.ru (unknown [IPv6:2a03:3100:c:13::5]) by mx1.freebsd.org (Postfix) with ESMTP id F257C8FC17; Tue, 5 Jul 2011 11:28:47 +0000 (UTC) Received: from eg.sd.rdtc.ru (localhost [127.0.0.1]) by eg.sd.rdtc.ru (8.14.4/8.14.4) with ESMTP id p65BShUp020220; Tue, 5 Jul 2011 18:28:43 +0700 (NOVST) (envelope-from egrosbein@rdtc.ru) Message-ID: <4E12F566.6000400@rdtc.ru> Date: Tue, 05 Jul 2011 18:28:38 +0700 From: Eugene Grosbein User-Agent: Mozilla/5.0 (X11; U; FreeBSD i386; ru-RU; rv:1.9.2.13) Gecko/20110112 Thunderbird/3.1.7 MIME-Version: 1.0 To: Adrian Minta References: <813678a855c90c49bf66c7084f88b45d.squirrel@mail.stsnet.ro> <20110704191451.GA12372@rdtc.ru> <4E12E32C.4030607@stsnet.ro> In-Reply-To: <4E12E32C.4030607@stsnet.ro> Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit Cc: freebsd-net@freebsd.org, Alexander Motin Subject: Re: FreeBSD 8.2 and MPD5 stability issues - update X-BeenThere: freebsd-net@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Networking and TCP/IP with FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 05 Jul 2011 11:28:49 -0000 05.07.2011 17:10, Adrian Minta wrote: CC'ing Alexander Motin, perhaps he knows why this happens in case of very high volume and rate of incoming connections. > A deeper debug of a failure looks like this: > > # grep "L28-6225" /var/log/mpd.log > Jul 5 13:06:39 lns mpd: [L28-6225] L2TP: Incoming call #70 via control > connection 0x80b7bfc10 accepted > Jul 5 13:06:39 lns mpd: [L28-6225] Link: OPEN event > Jul 5 13:06:39 lns mpd: [L28-6225] LCP: Open event > Jul 5 13:06:39 lns mpd: [L28-6225] LCP: state change Initial --> Starting > Jul 5 13:06:39 lns mpd: [L28-6225] LCP: LayerStart > Jul 5 13:06:40 lns mpd: [L28-6225] L2TP: Call #70 connected > Jul 5 13:06:40 lns mpd: [L28-6225] Link: UP event > Jul 5 13:06:40 lns mpd: [L28-6225] LCP: Up event > Jul 5 13:06:40 lns mpd: [L28-6225] LCP: state change Starting --> Req-Sent > Jul 5 13:06:40 lns mpd: [L28-6225] LCP: SendConfigReq #1 > Jul 5 13:06:42 lns mpd: [L28-6225] LCP: rec'd Configure Request #1 > (Req-Sent) > Jul 5 13:06:42 lns mpd: [L28-6225] LCP: SendConfigAck #1 > Jul 5 13:06:42 lns mpd: [L28-6225] LCP: state change Req-Sent --> Ack-Sent > Jul 5 13:06:42 lns mpd: [L28-6225] LCP: SendConfigReq #2 > Jul 5 13:06:43 lns mpd: [L28-6225] LCP: rec'd Configure Reject #4 > (Ack-Sent) > Jul 5 13:06:43 lns mpd: [L28-6225] Wrong id#, expecting 2 > Jul 5 13:06:44 lns mpd: [L28-6225] LCP: SendConfigReq #3 > Jul 5 13:06:46 lns mpd: [L28-6225] LCP: SendConfigReq #4 > Jul 5 13:06:48 lns mpd: [L28-6225] LCP: SendConfigReq #5 > Jul 5 13:06:48 lns mpd: [L28-6225] LCP: rec'd Configure Reject #5 > (Ack-Sent) > Jul 5 13:06:48 lns mpd: [L28-6225] LCP: SendConfigReq #6 > Jul 5 13:06:49 lns mpd: [L28-6225] LCP: rec'd Configure Request #1 > (Ack-Sent) > Jul 5 13:06:49 lns mpd: [L28-6225] LCP: SendConfigAck #1 > Jul 5 13:06:50 lns mpd: [L28-6225] LCP: SendConfigReq #7 > Jul 5 13:06:52 lns mpd: [L28-6225] LCP: SendConfigReq #8 > Jul 5 13:06:52 lns mpd: [L28-6225] LCP: rec'd Configure Reject #6 > (Ack-Sent) > Jul 5 13:06:52 lns mpd: [L28-6225] Wrong id#, expecting 8 > Jul 5 13:06:54 lns mpd: [L28-6225] LCP: SendConfigReq #9 > Jul 5 13:06:55 lns mpd: [L28-6225] LCP: rec'd Configure Request #1 > (Ack-Sent) > Jul 5 13:06:55 lns mpd: [L28-6225] LCP: SendConfigAck #1 > Jul 5 13:06:56 lns mpd: [L28-6225] LCP: SendConfigReq #10 > Jul 5 13:06:57 lns mpd: [L28-6225] LCP: rec'd Configure Reject #7 > (Ack-Sent) > Jul 5 13:06:57 lns mpd: [L28-6225] Wrong id#, expecting 10 > Jul 5 13:06:58 lns mpd: [L28-6225] LCP: SendConfigReq #11 > Jul 5 13:07:00 lns mpd: [L28-6225] LCP: SendConfigReq #12 > Jul 5 13:07:02 lns mpd: [L28-6225] LCP: rec'd Configure Request #1 > (Ack-Sent) > Jul 5 13:07:02 lns mpd: [L28-6225] LCP: SendConfigAck #1 > Jul 5 13:07:02 lns mpd: [L28-6225] LCP: rec'd Configure Reject #8 > (Ack-Sent) > Jul 5 13:07:02 lns mpd: [L28-6225] Wrong id#, expecting 12 > Jul 5 13:07:02 lns mpd: [L28-6225] LCP: SendConfigReq #13 > Jul 5 13:07:04 lns mpd: [L28-6225] LCP: SendConfigReq #14 > Jul 5 13:07:07 lns mpd: [L28-6225] LCP: SendConfigReq #15 > Jul 5 13:07:07 lns mpd: [L28-6225] LCP: rec'd Configure Reject #9 > (Ack-Sent) > Jul 5 13:07:07 lns mpd: [L28-6225] Wrong id#, expecting 15 > Jul 5 13:07:09 lns mpd: [L28-6225] LCP: parameter negotiation failed > Jul 5 13:07:09 lns mpd: [L28-6225] LCP: state change Ack-Sent --> Stopped > Jul 5 13:07:09 lns mpd: [L28-6225] LCP: LayerFinish > Jul 5 13:07:09 lns mpd: [L28-6225] L2TP: Call #70 terminated locally > Jul 5 13:07:09 lns mpd: [L28-6225] Link: DOWN event > Jul 5 13:07:09 lns mpd: [L28-6225] LCP: Close event > Jul 5 13:07:09 lns mpd: [L28-6225] LCP: state change Stopped --> Closed > Jul 5 13:07:09 lns mpd: [L28-6225] LCP: Down event > Jul 5 13:07:09 lns mpd: [L28-6225] LCP: state change Closed --> Initial > Jul 5 13:07:09 lns mpd: [L28-6225] Link: SHUTDOWN event > Jul 5 13:07:09 lns mpd: [L28-6225] Link: Shutdown > > Eugene Grosbein