"no matching session" in ng_pppoe.c 1.74.2.4? (RELENG_6)

[cpghost]

On Sun, 09 Dec 2007 23:52:01 +0200
Alexander Motin <mav at FreeBSD.org> wrote:

> cpghost wrote:
> >> I think such behaviour can take place if ppp daemon for some
> >> reason don't waits for reply but closes session immediately after
> >> sending connect request. If it so it also explains original "no
> >> matching session" errors as for the answer received time
> >> session/hook can already be destroyed.
> >>
> >> Provide please your ppp configuration files and part of detailed
> >> log file (set log All) describing connection attempts.
> > 
> > ppp.conf already sent. I don't have a 'set log All' turned on, but
> > maybe the following logfile of the aborted session would help?
> > 
> > http://www.cordula.ws/tests/ppp-tcpdump.txt
> 
> Here is part of your logs which proves my assumption that it is ppp
> who creates numerous sessions:
> 
> Dec  9 17:06:07 fw ppp[35265]: Phase: bundle: Establish
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: closed -> opening
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: Connected!
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: opening -> dial
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: dial -> carrier
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: Disconnected!
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: carrier -> hangup
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: Connect time: 0 secs:
> 0 octets in, 0 octets out
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: 7070012 packets in, 
> 6467630 packets out
> Dec  9 17:06:07 fw ppp[35265]: Phase:  total 0 bytes/sec, peak 0 
> bytes/sec on Sun Dec  9 17:06:07 2007
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: hangup -> closed
> Dec  9 17:06:07 fw ppp[35265]: Phase: bundle: Dead
> Dec  9 17:06:07 fw ppp[35265]: Phase: bundle: Establish
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: closed -> opening
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: Connected!
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: opening -> dial
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: dial -> carrier
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: Disconnected!
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: carrier -> hangup
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: Connect time: 0 secs:
> 0 octets in, 0 octets out
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: 7070012 packets in, 
> 6467630 packets out
> Dec  9 17:06:07 fw ppp[35265]: Phase:  total 0 bytes/sec, peak 0 
> bytes/sec on Sun Dec  9 17:06:07 2007
> Dec  9 17:06:07 fw ppp[35265]: Phase: deflink: hangup -> closed
> Dec  9 17:06:07 fw ppp[35265]: Phase: bundle: Dead
> Dec  9 17:06:07 fw ppp[35265]: Phase: bundle: Establish
> 
> For the some reason ppp logs "Disconnected!" message and terminates 
> session (which is strange as it have not logged any message from
> ng_ppp node) just to initiate new without delay. Could you enable any
> more logs to understant why is it "Disconnected!"?

If you let me know which one to turn on:

PPP ON fw> set log +connect
PPP ON fw> show log
Log:  Log:   CCP Chat Command Connect IPCP LCP Phase Tun Warning Error
Alert Local: Warning Error Alert
PPP ON fw>

I've briefly tried to turn on 'all' but since it's an active router
but a slow box, I'd rather not log this for very long... :(
it generates huge logs VERY fast.

PPP ON fw> set log all
PPP ON fw> show log
Log:   Async CBCP CCP Chat Command Connect Debug DNS Filter HDLC ID0
IPCP IPV6CP LCP LQM Phase Physical Radius Sync TCP/IP Timer Tun Warning
Error Alert Local: Warning Error Alert
PPP ON fw> set log phase chat lcp ipcp ccp tun command
PPP ON fw> 

Should I try to re-connect with all enabled now? Of course, it will
reset the 24h period...

-cpghost.

-- 
Cordula's Web. http://www.cordula.ws/