[fli4l] fli4l stellt die Verbindung zum Internet per PPPoE erst nach Reboot her

[Christoph Schulz]

Hallo!

Am Sun, 21 Aug 2016 16:35:02 +0200 schrieb Thomas Grunenberg:

>>> Mein fli4l läuft hinter einem Vigor 130 (als Modem) an einem
>>> O2-Anschluss, der von der Telekom bereitgestellt wird. Der fli4l wählt
>>> sich über PPPoE ins Internet.
>>>
>>> Heute hatte ich das Problem, dass der fli4l meinte, mit dem Internet
>>> verbunden zu sein (auf der Console meldet fli4lctrl status => online),
>>> obwohl das Internet nicht erreichbar war. Ich habe einige Dateien
>>> (messages, dial und supportinfos) gesichert.
>>> [...]
>>> Sind das nur "Nachwehen" der Telekom-Störung? Könnt Ihr mir helfen das
>>> Problem einzugrenzen?

Aus den Logs geht hervor, dass der fli4l sich um 21.8. um 4:25 Uhr noch 
erfolgreich die PPP-Verbindung aufbauen konnte:

Aug 21 04:25:06 fli4l local2.info pppd[1099]: Starting link
[...]
Aug 21 04:25:21 fli4l local2.notice pppd[1099]: Connect: ppp0 <--> eth0
[...]
Aug 21 04:25:23 fli4l local2.notice pppd[1099]: peer from calling number 
<mac> authorized
Aug 21 04:25:23 fli4l local2.warn pppd[1099]: Local IP address changed 
to ...
Aug 21 04:25:23 fli4l local2.warn pppd[1099]: Remote IP address changed 
to ...

Um 4:51 Uhr warf dich der Peer raus:

Aug 21 04:51:06 fli4l local2.debug pppd[1099]: rcvd [LCP TermReq id=0x7c]
Aug 21 04:51:06 fli4l local2.info pppd[1099]: LCP terminated by peer
Aug 21 04:51:06 fli4l local2.info pppd[1099]: Connect time 25.7 minutes.
Aug 21 04:51:06 fli4l local2.info pppd[1099]: Sent 48577 bytes, received 
30648 bytes.

Danach versuchte sich der fli4l wieder einzuwählen -- vergeblich, 
angeblich konnte er sich nicht erfolgreich anmelden:

Aug 21 04:58:01 fli4l local2.info pppd[1099]: Starting link
[...]
Aug 21 04:58:06 fli4l local2.notice pppd[1099]: Connect: ppp0 <--> eth0
[...]
Aug 21 04:58:36 fli4l local2.err pppd[1099]: No response to PAP 
authenticate-requests
Aug 21 04:58:36 fli4l local2.debug pppd[1099]: sent [LCP TermReq id=0x7 
"Failed to authenticate ourselves to peer"]
Aug 21 04:58:36 fli4l local2.debug pppd[1099]: rcvd [LCP TermAck id=0x7]

Das hat aber um 5:28 Uhr wieder funktioniert:

Aug 21 05:28:01 fli4l local2.info pppd[1099]: Starting link
[...]
Aug 21 05:28:06 fli4l local2.notice pppd[1099]: Connect: ppp0 <--> eth0
[...]
Aug 21 05:28:08 fli4l local2.notice pppd[1099]: PAP authentication 
succeeded
[...]
Aug 21 05:28:08 fli4l local2.warn pppd[1099]: Local IP address changed 
to ...
Aug 21 05:28:08 fli4l local2.warn pppd[1099]: Remote IP address changed 
to ...

Eine knappe Minute später wurde der fli4l wieder rausgeworfen:

Aug 21 05:28:56 fli4l local2.debug pppd[1099]: rcvd [LCP TermReq id=0xc3]
Aug 21 05:28:56 fli4l local2.info pppd[1099]: LCP terminated by peer
Aug 21 05:28:56 fli4l local2.info pppd[1099]: Connect time 0.8 minutes.
Aug 21 05:28:56 fli4l local2.info pppd[1099]: Sent 2144 bytes, received 
2071 bytes.

Diese ganzen Probleme haben also mit dem fli4l nichts zu tun. Warum dich 
dein Internet-Provider ständig via LCP rauswirft, weiß ich nicht. 
Jedenfalls ist es absolut albern, eine Sekunde nach Aufbau der IPv4-
Verbindung diese wieder abzubauen:

Aug 21 09:00:09 fli4l local2.warn pppd[1099]: Local IP address changed 
to ...
Aug 21 09:00:09 fli4l local2.warn pppd[1099]: Remote IP address changed 
to ...
[...]
Aug 21 09:00:10 fli4l local2.debug pppd[1099]: rcvd [LCP TermReq id=0x57]
Aug 21 09:00:10 fli4l local2.info pppd[1099]: LCP terminated by peer
Aug 21 09:00:10 fli4l local2.info pppd[1099]: Connect time 0.0 minutes.
Aug 21 09:00:10 fli4l local2.info pppd[1099]: Sent 0 bytes, received 0 
bytes.

Die Situation um 16:00 Uhr war eine andere: Hier hatte der fli4l 
definitiv keine PPP-Verbindung, und zwar seit 9:02 Uhr nicht:

Aug 21 09:02:16 fli4l local2.debug pppd[1099]: rcvd [LCP TermReq id=0xc8]
Aug 21 09:02:16 fli4l local2.info pppd[1099]: LCP terminated by peer
Aug 21 09:02:16 fli4l local2.info pppd[1099]: Connect time 1.0 minutes.
Aug 21 09:02:16 fli4l local2.info pppd[1099]: Sent 0 bytes, received 40 
bytes.
Aug 21 09:02:16 fli4l local2.debug pppd[1099]: sent [LCP TermAck id=0xc8]
Aug 21 09:02:19 fli4l local2.notice pppd[1099]: Connection terminated.

Warum er sich danach nicht wieder eingewählt hat, weiß ich nicht genau. 
Anscheinend kam das dyndns-Paket mit dem schnellen Auflegen nicht klar, 
denn der Prozess "hängt":

15402 root      1204 S N  {dyndns-update.s} /bin/sh /usr/bin/dyndns-
update.sh -s -l /var/run/dyndns/dyndns_ip-up.13950 <...> pppoe

Das ist ein bekanntes Problem bei fli4l: Wenn eines der ip-up- oder ip-
down-Skripte hängen bleibt, gerät die ganze Einwahl-Maschinerie etwas ins 
Wanken. Für fli4l 4.x habe ich einige Ideen, wie ich das verbessern kann. 
Wieviel davon in fli4l 3.10.x umgesetzt werden kann, kann ich nicht 
sagen. Im Falle von dyndns müsste man alle aufgerufenen Programme 
daraufhin überprüfen, ob diese bei nicht funktionierender Internet-
Anbindung hängen könnten und ggf. andere Timeout-Parameter o.ä. übergeben.


Viele Grüße,
-- 
Christoph Schulz
[fli4l-Team]