user ppp and PPPoE bridging

[freebsd at dreamchaser.org]

Nikos Vassiliadis wrote:

> You said you had wrong encapsulation type. Did you make any progress?

Yes.
Changing the encapsulation type brought the line up,
and things hobbled along...
However, the line is dropped after a few minutes,
apparently a result of not being able to determine line quality:

Oct 24 12:39:06 nightmare ppp[859]: tun0: Phase: deflink: ** Too many LQR packets lost **
Oct 24 12:39:06 nightmare ppp[859]: tun0: LQM: deflink: Too many LQR packets lost
Oct 24 12:39:06 nightmare ppp[859]: tun0: CCP: deflink: State change Stopped --> Closed
Oct 24 12:39:06 nightmare ppp[859]: tun0: CCP: deflink: State change Closed --> Initial
Oct 24 12:39:06 nightmare ppp[859]: tun0: LCP: deflink: LayerDown
Oct 24 12:39:06 nightmare ppp[859]: tun0: LCP: deflink: State change Opened --> Starting
Oct 24 12:39:06 nightmare ppp[859]: tun0: Phase: deflink: open -> lcp
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: route_UpdateMTU (5)
Oct 24 12:39:06 nightmare ppp[859]: tun0: TCP/IP: route_UpdateMTU: Netif: 5 (tun0), dst 0.0.0.0/0, mtu 1500
Oct 24 12:39:06 nightmare ppp[859]: tun0: TCP/IP: route_UpdateMTU: Netif: 5 (tun0), dst 216.47.48.1, mtu 1500
Oct 24 12:39:06 nightmare ppp[859]: tun0: TCP/IP: route_UpdateMTU: Netif: 5 (tun0), dst ff01:5::/32, mtu 1500
Oct 24 12:39:06 nightmare ppp[859]: tun0: TCP/IP: route_UpdateMTU: Netif: 5 (tun0), dst ff02:5::/32, mtu 1500
Oct 24 12:39:06 nightmare ppp[859]: tun0: IPCP: deflink: LayerDown: 12.32.44.142
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: ReadSystem: Can't open /etc/ppp/ppp.linkdown.
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: ReadSystem: Can't open /etc/ppp/ppp.linkdown.
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: ReadSystem: Can't open /etc/ppp/ppp.linkdown.
Oct 24 12:39:06 nightmare ppp[859]: tun0: IPCP: deflink: State change Opened --> Starting
Oct 24 12:39:06 nightmare ppp[859]: tun0: IPCP: deflink: LayerFinish.
Oct 24 12:39:06 nightmare ppp[859]: tun0: IPCP: Connect time: 331 secs: 2253 octets in, 1584 octets out
Oct 24 12:39:06 nightmare ppp[859]: tun0: IPCP: 24 packets in, 25 packets out
Oct 24 12:39:06 nightmare ppp[859]: tun0: IPCP:  total 11 bytes/sec, peak 275 bytes/sec on Wed Oct 24 12:34:43 2007
Oct 24 12:39:06 nightmare ppp[859]: tun0: IPCP: deflink: State change Starting --> Initial
Oct 24 12:39:06 nightmare ppp[859]: tun0: Phase: bundle: Terminate
Oct 24 12:39:06 nightmare ppp[859]: tun0: LCP: deflink: LayerFinish
Oct 24 12:39:06 nightmare ppp[859]: tun0: LCP: deflink: State change Starting --> Initial
Oct 24 12:39:06 nightmare ppp[859]: tun0: Phase: deflink: Disconnected!
Oct 24 12:39:06 nightmare ppp[859]: tun0: Phase: deflink: lcp -> logout
Oct 24 12:39:06 nightmare ppp[859]: tun0: Phase: deflink: Disconnected!
Oct 24 12:39:06 nightmare ppp[859]: tun0: Phase: deflink: logout -> hangup
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: deflink: Close
Oct 24 12:39:06 nightmare ppp[859]: tun0: Phase: deflink: Connect time: 332 secs: 3044 octets in, 2789 octets out
Oct 24 12:39:06 nightmare ppp[859]: tun0: Phase: deflink: 70 packets in, 77 packets out
Oct 24 12:39:06 nightmare ppp[859]: tun0: Phase:  total 17 bytes/sec, peak 315 bytes/sec on Wed Oct 24 12:34:46 2007
Oct 24 12:39:06 nightmare ppp[859]: tun0: Phase: deflink: hangup -> closed
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: route_IfDelete (5)
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: Found 0.0.0.0/0 216.47.48.1
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: route_IfDelete: Skip it (pass 0)
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: Found 216.47.48.1 12.32.44.142
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: route_IfDelete: Skip it (pass 0)
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: Found ff01:5::/32 <AF_UNSPEC>
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: route_IfDelete: Skip it (pass 0)
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: Found ff02:5::/32 <AF_UNSPEC>
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: route_IfDelete: Skip it (pass 0)
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: Found 0.0.0.0/0 216.47.48.1
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: wrote 124: cmd = Delete, dst = 0.0.0.0/0, gateway = <none>
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: Found 216.47.48.1 12.32.44.142
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: wrote 108: cmd = Delete, dst = 216.47.48.1, gateway = <none>
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: Found ff01:5::/32 <AF_UNSPEC>
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: wrote 148: cmd = Delete, dst = ff01:5::/32, gateway = <none>
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: Found ff02:5::/32 <AF_UNSPEC>
Oct 24 12:39:06 nightmare ppp[859]: tun0: Debug: wrote 148: cmd = Delete, dst = ff02:5::/32, gateway = <none>
Oct 24 12:39:06 nightmare ppp[859]: tun0: Phase: bundle: Dead

During initial protocol negotiation, it looks like come sort of compression
is disallowed, but it doesn't seem like that should cause the line to be
dropped later:

Oct 24 12:33:35 nightmare ppp[859]: tun0: LCP: deflink: RecvProtocolRej(2) state = Opened
Oct 24 12:33:35 nightmare ppp[859]: tun0: LCP: deflink: -- Protocol 0x80fd (Compression Control Protocol) was rejected!
Oct 24 12:33:35 nightmare ppp[859]: tun0: CCP: deflink: State change Req-Sent --> Stopped
Oct 24 12:33:35 nightmare ppp[859]: tun0: IPCP: deflink: RecvConfigRej(1) state = Ack-Sent
Oct 24 12:33:35 nightmare ppp[859]: tun0: IPCP:  COMPPROTO[6] 16 VJ slots with slot compression
Oct 24 12:33:35 nightmare ppp[859]: tun0: IPCP: deflink: SendConfigReq(2) state = Ack-Sent

And after the line is up, I see this:

Oct 24 12:33:35 nightmare ppp[859]: tun0: Debug: deflink: PPPoE:ed1: Cannot determine bandwidth

I presume this is a result of the lost LQR packets.

Prior to closing the line, there are a number of what look like sync
attempts; they look to me like they succeed:

Oct 24 12:38:36 nightmare ppp[859]: tun0: Debug: deflink: DescriptorRead: read 14/2048 from 3
Oct 24 12:38:36 nightmare ppp[859]: tun0: Debug: proto_LayerPull: unknown -> 0xc021
Oct 24 12:38:36 nightmare ppp[859]: tun0: Debug: link_PullPacket: Despatch proto 0xc021
Oct 24 12:38:36 nightmare ppp[859]: tun0: LCP: deflink: RecvEchoRequest(30) state = Opened
Oct 24 12:38:36 nightmare ppp[859]: tun0: LCP: deflink: SendEchoReply(30) state = Opened
Oct 24 12:38:36 nightmare ppp[859]: tun0: Debug: fsm_Output
Oct 24 12:38:36 nightmare ppp[859]: tun0: Debug:  0a 1e 00 0c 0b 58 fc 84 0b 58 fc 84              .....X...X..
Oct 24 12:38:36 nightmare ppp[859]: tun0: Debug: proto_LayerPush: Using 0xc021
Oct 24 12:38:36 nightmare ppp[859]: tun0: Debug: link_PushPacket: Transmit proto 0xc021
Oct 24 12:38:36 nightmare ppp[859]: tun0: Debug: m_enqueue: len = 1
Oct 24 12:38:36 nightmare ppp[859]: tun0: Debug: m_dequeue: queue len = 1
Oct 24 12:38:36 nightmare ppp[859]: tun0: Debug: link_Dequeue: Dequeued from queue 1, containing 0 more packets
Oct 24 12:38:36 nightmare ppp[859]: tun0: Debug: deflink: DescriptorWrite: wrote 14(14) to 3
Oct 24 12:38:36 nightmare ppp[859]: tun0: LQM: deflink: Output:
Oct 24 12:38:36 nightmare ppp[859]: tun0: LQM:   Magic:          0b58fc84   LastOutLQRs:    00000005
Oct 24 12:38:36 nightmare ppp[859]: tun0: LQM:   LastOutPackets: 20464846   LastOutOctets:  46454d44
Oct 24 12:38:36 nightmare ppp[859]: tun0: LQM:   PeerInLQRs:     00000005   PeerInPackets:  0000002f
Oct 24 12:38:36 nightmare ppp[859]: tun0: LQM:   PeerInDiscards: 00000000   PeerInErrors:   00000000
Oct 24 12:38:36 nightmare ppp[859]: tun0: LQM:   PeerInOctets:   00000a6c   PeerOutLQRs:    0000000b
Oct 24 12:38:36 nightmare ppp[859]: tun0: LQM:   PeerOutPackets: 00000049   PeerOutOctets:  00000ac2

The above summary appears to indicate that line quality requests are
being transferred; so what's with the too many LQR packets lost message?

Finally,
Where does the initial IP address used in the negotiation come from?
I did not specify specific IP address assignment,
yet the request appears to have asked for 12.32.36.65
This is the IP of the other interface on the machine,
and my ppp.conf has no mention of it.

  Can you also check the number of cells going out/coming in from the ATM
> interface?

I'm not sure what you mean by this...

Thanks for any help;
I'm going to be out for a day or so,
so may be slow to reply

Gary