Date: Wed, 29 Feb 2012 03:09:30 GMT From: Volodymyr Kostyrko <c.kworr@gmail.com> To: freebsd-gnats-submit@FreeBSD.org Subject: ports/165544: net/mpd5 fails to listen on tcp port Message-ID: <201202290309.q1T39Ude036341@red.freebsd.org> Resent-Message-ID: <201202290410.q1T4AGZ1022243@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
>Number: 165544
>Category: ports
>Synopsis: net/mpd5 fails to listen on tcp port
>Confidential: no
>Severity: non-critical
>Priority: low
>Responsible: freebsd-ports-bugs
>State: open
>Quarter:
>Keywords:
>Date-Required:
>Class: sw-bug
>Submitter-Id: current-users
>Arrival-Date: Wed Feb 29 04:10:16 UTC 2012
>Closed-Date:
>Last-Modified:
>Originator: Volodymyr Kostyrko
>Release: RELENG_8_2
>Organization:
>Environment:
FreeBSD urquan.xim.bz 8.2-RELEASE-p5 FreeBSD 8.2-RELEASE-p5 #1: Mon Dec 26 23:37:20 EET 2011 arcade@urquan.xim.bz:/usr/obj/usr/src/sys/MINIMAL amd64
>Description:
Last mpd log starts on Jan 3 2011. There was nothing like this before.
Config:
startup:
set user root blablabla admin
set console self 127.0.0.1 5005
set console open
set web self 127.0.0.1 5006
set web open
default:
load in_server
in_server:
create bundle template IN
set bundle yes compression crypt-reqd
set ccp yes deflate pred1 mppc
set mppc yes e128 compress
set ipcp ranges 172.31.0.5/32 0.0.0.0/32
create link template in tcp
set auth max-logins 1
set link action bundle IN
set link keep-alive 5 20
set link no pap chap eap
set link enable chap
set link yes incoming multilink passive
set tcp self 109.72.152.19 9
Yesterday in the morning when nothing happens at server as I was surely sleeping:
Feb 28 08:12:28 urquan mpd: [in-1] LCP: no reply to 1 echo request(s)
Feb 28 08:12:33 urquan mpd: [in-1] LCP: no reply to 2 echo request(s)
Feb 28 08:12:39 urquan mpd: [in-1] LCP: no reply to 3 echo request(s)
Feb 28 08:12:39 urquan mpd: [in-1] LCP: peer not responding to echo requests
Feb 28 08:12:39 urquan mpd: [in-1] LCP: state change Opened --> Stopping
Feb 28 08:12:39 urquan mpd: [in-1] Link: Leave bundle "IN-1"
Feb 28 08:12:39 urquan mpd: [IN-1] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Feb 28 08:12:39 urquan mpd: [IN-1] IPCP: Close event
Feb 28 08:12:39 urquan mpd: [IN-1] IPCP: state change Opened --> Closing
Feb 28 08:12:39 urquan mpd: [IN-1] IPCP: SendTerminateReq #2
Feb 28 08:12:39 urquan mpd: [IN-1] IPCP: LayerDown
Feb 28 08:12:39 urquan mpd: [IN-1] IFACE: Down event
Feb 28 08:12:39 urquan mpd: [IN-1] CCP: Close event
Feb 28 08:12:39 urquan mpd: [IN-1] CCP: state change Opened --> Closing
Feb 28 08:12:39 urquan mpd: [IN-1] CCP: SendTerminateReq #90
Feb 28 08:12:39 urquan mpd: [IN-1] CCP: LayerDown
Feb 28 08:12:39 urquan mpd: [IN-1] IPCP: Down event
Feb 28 08:12:39 urquan mpd: [IN-1] IPCP: LayerFinish
Feb 28 08:12:39 urquan mpd: [IN-1] Bundle: No NCPs left. Closing links...
Feb 28 08:12:39 urquan mpd: [IN-1] IPCP: state change Closing --> Initial
Feb 28 08:12:39 urquan mpd: [IN-1] CCP: Down event
Feb 28 08:12:39 urquan mpd: [IN-1] CCP: LayerFinish
Feb 28 08:12:39 urquan mpd: [IN-1] CCP: state change Closing --> Initial
Feb 28 08:12:39 urquan mpd: [IN-1] Bundle: Shutdown
Feb 28 08:12:39 urquan mpd: [in-1] LCP: SendTerminateReq #2
Feb 28 08:12:39 urquan mpd: [in-1] LCP: LayerDown
Feb 28 08:12:41 urquan mpd: [in-1] LCP: SendTerminateReq #3
Feb 28 08:12:43 urquan mpd: [in-1] LCP: state change Stopping --> Stopped
Feb 28 08:12:43 urquan mpd: [in-1] LCP: LayerFinish
Feb 28 08:12:43 urquan mpd: [in-1] Link: DOWN event
Feb 28 08:12:43 urquan mpd: [in-1] LCP: Close event
Feb 28 08:12:43 urquan mpd: [in-1] LCP: state change Stopped --> Closed
Feb 28 08:12:43 urquan mpd: [in-1] LCP: Down event
Feb 28 08:12:43 urquan mpd: [in-1] LCP: state change Closed --> Initial
Feb 28 08:12:43 urquan mpd: [in-1] Link: SHUTDOWN event
Feb 28 08:12:43 urquan mpd: [in-1] Link: Shutdown
It was reconnected and half an hour later:
Feb 28 08:49:45 urquan mpd: [in-1] LCP: no reply to 1 echo request(s)
Feb 28 08:49:50 urquan mpd: [in-1] LCP: no reply to 2 echo request(s)
Feb 28 08:49:55 urquan mpd: [in-1] LCP: no reply to 3 echo request(s)
Feb 28 08:49:55 urquan mpd: [in-1] LCP: peer not responding to echo requests
Feb 28 08:49:55 urquan mpd: [in-1] LCP: state change Opened --> Stopping
Feb 28 08:49:55 urquan mpd: [in-1] Link: Leave bundle "IN-1"
Feb 28 08:49:55 urquan mpd: [IN-1] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Feb 28 08:49:55 urquan mpd: [IN-1] IPCP: Close event
Feb 28 08:49:55 urquan mpd: [IN-1] IPCP: state change Opened --> Closing
Feb 28 08:49:55 urquan mpd: [IN-1] IPCP: SendTerminateReq #2
Feb 28 08:49:55 urquan mpd: [IN-1] IPCP: LayerDown
Feb 28 08:49:55 urquan mpd: [IN-1] IFACE: Down event
Feb 28 08:49:55 urquan mpd: [IN-1] CCP: Close event
Feb 28 08:49:55 urquan mpd: [IN-1] CCP: state change Opened --> Closing
Feb 28 08:49:55 urquan mpd: [IN-1] CCP: SendTerminateReq #3
Feb 28 08:49:55 urquan mpd: [IN-1] CCP: LayerDown
Feb 28 08:49:55 urquan mpd: [IN-1] IPCP: Down event
Feb 28 08:49:55 urquan mpd: [IN-1] IPCP: LayerFinish
Feb 28 08:49:55 urquan mpd: [IN-1] Bundle: No NCPs left. Closing links...
Feb 28 08:49:55 urquan mpd: [IN-1] IPCP: state change Closing --> Initial
Feb 28 08:49:55 urquan mpd: [IN-1] CCP: Down event
Feb 28 08:49:55 urquan mpd: [IN-1] CCP: LayerFinish
Feb 28 08:49:55 urquan mpd: [IN-1] CCP: state change Closing --> Initial
Feb 28 08:49:55 urquan mpd: [IN-1] Bundle: Shutdown
Feb 28 08:49:55 urquan mpd: [in-1] LCP: SendTerminateReq #2
Feb 28 08:49:55 urquan mpd: [in-1] LCP: LayerDown
Feb 28 08:49:57 urquan mpd: [in-1] LCP: SendTerminateReq #3
Feb 28 08:49:59 urquan mpd: [in-1] LCP: state change Stopping --> Stopped
Feb 28 08:49:59 urquan mpd: [in-1] LCP: LayerFinish
Feb 28 08:49:59 urquan mpd: [in-1] Link: DOWN event
Feb 28 08:49:59 urquan mpd: [in-1] LCP: Close event
Feb 28 08:49:59 urquan mpd: [in-1] LCP: state change Stopped --> Closed
Feb 28 08:49:59 urquan mpd: [in-1] LCP: Down event
Feb 28 08:49:59 urquan mpd: [in-1] LCP: state change Closed --> Initial
Feb 28 08:49:59 urquan mpd: [in-1] Link: SHUTDOWN event
Feb 28 08:49:59 urquan mpd: [in-1] Link: Shutdown
After that server becomes unresponsive. Reloading it gived me:
Feb 28 10:13:16 urquan mpd: caught fatal signal term
Feb 28 10:13:18 urquan mpd: [IN] Bundle: Shutdown
Feb 28 10:13:18 urquan mpd: [in] Link: Shutdown
Feb 28 10:13:18 urquan mpd: TCP: stop waiting for connection on 109.72.152.19 9
Feb 28 10:13:18 urquan mpd: process 1039 terminated
Feb 28 10:13:18 urquan mpd: Multi-link PPP daemon for FreeBSD
Feb 28 10:13:18 urquan mpd:
Feb 28 10:13:18 urquan mpd: process 41383 started, version 5.6 (root@urquan.xim.bz 13:37 23-Dec-2011)
Feb 28 10:13:18 urquan mpd: CONSOLE: listening on 127.0.0.1 5005
Feb 28 10:13:18 urquan mpd: web: listening on 127.0.0.1 5006
Feb 28 10:13:18 urquan mpd: TCP: can't bind() ksocket node: Invalid argument
Feb 28 10:13:18 urquan mpd: TCP: stop waiting for connection on UNSPEC 0
Feb 28 10:13:18 urquan mpd: TCP: waiting for connection on 109.72.152.19 9
But mpd was not listening on port 9. sockstat shows it was only listening on ports 5005 and 5006.
Recompiling port and restarting service or server (warm boot) hasn't changed anything. MPD just doesn't listen for incoming connections.
Hours ago I thought I should gather some data by turning on detailed logging. Surprise, after starting with:
log +BUND2 +LCP2 +AUTH2 +IPCP2 +IPV6CP2 +CCP2 +ECP2 +ECHO +PHYS2 +PHYS3 +CHAT2 +IFACE2 +FRAME +RADIUS2 +EVENTS
mpd binds the port and continues to work.
Feb 28 15:46:15 urquan mpd: process 85797 started, version 5.6 (root@urquan.xim.bz 15:37 28-Feb-2012)
Feb 28 15:46:15 urquan mpd: CONSOLE: listening on 127.0.0.1 5005
Feb 28 15:46:15 urquan mpd: web: listening on 127.0.0.1 5006
Feb 28 15:46:15 urquan mpd: EVENT: Registering event EVENT_READ MsgEvent() at msg.c:72
Feb 28 15:46:15 urquan mpd: EVENT: Registering event EVENT_READ MsgEvent() done at msg.c:72
Feb 28 15:46:15 urquan mpd: TCP: can't bind() ksocket node: Invalid argument
Feb 28 15:46:15 urquan mpd: TCP: stop waiting for connection on UNSPEC 0
Feb 28 15:46:15 urquan mpd: EVENT: Unregistering event (null) at tcp.c:831
Feb 28 15:46:15 urquan mpd: EVENT: Unregistering event (null) done at tcp.c:831
Feb 28 15:46:15 urquan mpd: TCP: waiting for connection on 109.72.152.19 9
Feb 28 15:46:15 urquan mpd: EVENT: Registering event EVENT_READ TcpAcceptEvent() at tcp.c:809
Feb 28 15:46:15 urquan mpd: EVENT: Registering event EVENT_READ TcpAcceptEvent() done at tcp.c:809
Feb 28 15:46:15 urquan mpd: EVENT: Processing event EVENT_TIMEOUT ConfigRead() done
Feb 28 15:46:16 urquan mpd: EVENT: Processing event EVENT_READ TcpAcceptEvent()
Feb 28 15:46:16 urquan mpd: Incoming TCP connection from UNSPEC 0
Feb 28 15:46:16 urquan mpd: [in-1] Accepting TCP connection from UNSPEC 0
Feb 28 15:46:16 urquan mpd: EVENT: Message 1 to LinkMsg() sent
Feb 28 15:46:16 urquan mpd: EVENT: Registering event EVENT_READ TcpAcceptEvent() at tcp.c:511
Feb 28 15:46:16 urquan mpd: EVENT: Registering event EVENT_READ TcpAcceptEvent() done at tcp.c:511
Feb 28 15:46:16 urquan mpd: EVENT: Processing event EVENT_READ TcpAcceptEvent() done
Feb 28 15:46:16 urquan mpd: EVENT: Processing event EVENT_READ MsgEvent()
Feb 28 15:46:16 urquan mpd: EVENT: Message 1 to LinkMsg() received
Feb 28 15:46:16 urquan mpd: [in-1] Link: OPEN event
Feb 28 15:46:16 urquan mpd: [in-1] LCP: Open event
Feb 28 15:46:16 urquan mpd: [in-1] LCP: state change Initial --> Starting
Feb 28 15:46:16 urquan mpd: EVENT: Stopping timer "(null)" (null)() at fsm.c:190
Feb 28 15:46:16 urquan mpd: [in-1] LCP: LayerStart
Feb 28 15:46:17 urquan mpd: EVENT: Message 1 to PhysMsg() sent
Feb 28 15:46:17 urquan mpd: EVENT: Message 1 to LinkMsg() processed
Feb 28 15:46:17 urquan mpd: EVENT: Message 1 to PhysMsg() received
Feb 28 15:46:17 urquan mpd: [in-1] device: OPEN event
Feb 28 15:46:17 urquan mpd: [in-1] TcpOpen() on incoming call
Feb 28 15:46:17 urquan mpd: [in-1] device: UP event
Feb 28 15:46:17 urquan mpd: [in-1] Link: UP event
Feb 28 15:46:17 urquan mpd: [in-1] Link: origination is remote
Feb 28 15:46:17 urquan mpd: [in-1] LCP: Up event
Feb 28 15:46:17 urquan mpd: [in-1] LCP: state change Starting --> Req-Sent
Feb 28 15:46:17 urquan mpd: [in-1] LCP: phase shift DEAD --> ESTABLISH
Feb 28 15:46:17 urquan mpd: EVENT: Stopping timer "(null)" (null)() at fsm.c:531
>How-To-Repeat:
>Fix:
>Release-Note:
>Audit-Trail:
>Unformatted:
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201202290309.q1T39Ude036341>