xDSL.at

von **dfx** » Fr 24 Sep, 2004 08:57

hat der pptp client wieder wegen "buffering packets" o.ä. gemeckert? (müßte direkt oberhalb der shutdown meldungen des pptp stehen..)

von **marvin42** » Fr 24 Sep, 2004 09:01

dfx hat geschrieben:paar blöde fragen:

erstmal der erste eintrag:

Code: Alles auswählen
Sep 19 15:25:12 Server pppd[2037]: Using interface ppp0 Sep 19 15:25:12 Server pppd[2037]: local IP address 10.64.64.64 Sep 19 15:25:12 Server pppd[2037]: remote IP address 10.112.112.112

was ist das?

dein setup ist ja so, daß pppd sich nie beendet. wie wird der pptp client aufgerufen?

Vielleicht zur Erklärung der Inhalt der /etc/ppp/peers file:

Code: Alles auswählen: pty "pptp-client 10.0.0.138 --nolaunchpppd --sync --ignorebuffer --loglevel 0 --logstring pptp-client" sync noauth noipdefault noauth nodetach hide-password user "anonymer" demand persist holdoff 3 maxfail 0 usepeerdns connect /bin/true precompiled-active-filter /etc/ppp/filter idle 600

Der pppd startet den pptp-client erst bei einem Verbindungsaufbau.

lahe hat geschrieben:Sep 23 20:37:50 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 12 'Call-Clear-Request'
Sep 23 20:37:50 Server syslog: pptp-client log[pptp_conn_close:pptp_ctrl.c:425]: Closing PPTP connection
...
Sep 23 20:37:50 Server pppd[2037]: Connection terminated.
Sep 23 20:37:50 Server pppd[2037]: Connect time 48.2 minutes.

Das suggeriert, daß der Patch nicht geholfen hat, leider keine vollständigen Logs :cry:

Gibts ausser der Frage nach den Logs noch Ideen zur Problemsuche (vielleicht von Inode-Seite?)?

Marvin

von **marvin42** » Fr 24 Sep, 2004 10:05

dfx hat geschrieben:hat der pptp client wieder wegen "buffering packets" o.ä. gemeckert? (müßte direkt oberhalb der shutdown meldungen des pptp stehen..)

Der default wert für log level ist dummerweise , wenn davor nix steht, bitte das LogLevel hochsetzen (es geht rauf bis zwei) und möglichst das gesamte log zur Verfügung stellen ...

Also idealerweise:

Code: Alles auswählen: PPTP_CLIENT_LOGLEVEL='2' PPTP_DEBUG='yes'

Marvin

von **lahe** » Sa 25 Sep, 2004 10:06

Hallo,

habe wieder einen Log auf http://members.inode.at/b.aichberger/massages.txt hochgeladen.
Diesmal mit loglevel 2
Die Verbindung wurde 1mal um 20:08:27 nach 99.3min und einmal um 20:49:48 nach 41.1min getrennt

Seit der letzten Trennung um 20:49:48 ist er nun fast 15 Stunden online.
Alle Zeitangaben in UTC.

lahe

von **marvin42** » Sa 25 Sep, 2004 13:54

lahe hat geschrieben:Hallo,

habe wieder einen Log auf http://members.inode.at/b.aichberger/massages.txt hochgeladen.
Diesmal mit loglevel 2

Keine gedroppten Pakete, meine aktuelle Vermutung ist, dass die Verbindung aufgrund eines ausstehenden echo replies beendet wird:

pptp rfc hat geschrieben:3.1.4 Keep Alives and Timers

A control connection SHOULD be closed by closing the underlying TCP connection under the following circumstances:

1 If a control connection is not in the established state (i.e., Start-Control-Connection-Request and Start-Control-Connection- Reply have not been exchanged), a control connection SHOULD be closed after 60 seconds by a peer waiting for a Start-Control- Connection-Request or Start-Control-Connection-Reply message.

2 If a peer's control connection is in the established state and has not received a control message for 60 seconds, it SHOULD send a Echo-Request message. If an Echo-Reply is not received 60 seconds after the Echo-Request message transmission, the control connection SHOULD be closed.

Ich habe mal einen pptp-client gebaut, der ein paar fehlende echo replies toleriert, liegt auf http://www.fli4l.de/german/extern/bugs/fli4l-2.1.8-bug.html. BEschreibung ist auch auf der Webseite ...

MfG,
Marvin

von **lahe** » Sa 25 Sep, 2004 22:00

....schon wieder ein Log. Diesmal mit installiertem pptp-client von der fli4l Page mit loglevel 1
http://members.inode.at/b.aichberger/massages1.txt Zeit(UTC)

lahe

von **marvin42** » Sa 25 Sep, 2004 22:18

lahe hat geschrieben:....schon wieder ein Log. Diesmal mit installiertem pptp-client von der fli4l Page mit loglevel 1
http://members.inode.at/b.aichberger/massages1.txt Zeit(UTC)

lahe

Die relevanten Teile:

Code: Alles auswählen: Sep 25 22:17:37 Server pppd[1945]: Local IP address changed to 83.64.199.231 Sep 25 22:17:37 Server pppd[1945]: Remote IP address changed to 62.99.171.97 Sep 25 22:17:37 Server pppd[1945]: sent [IP data] 45 00 00 39 f4 08 40 00 ... Sep 25 22:18:34 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 22:18:34 Server syslog: pptp-client log[logecho:pptp_ctrl.c:662]: Echo Reply received. ... Sep 25 23:11:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:11:41 Server syslog: pptp-client log[logecho:pptp_ctrl.c:662]: Echo Reply received. Sep 25 23:12:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:13:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 4 left until closing down connection Sep 25 23:13:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:14:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 3 left until closing down connection Sep 25 23:14:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:15:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 2 left until closing down connection Sep 25 23:15:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:16:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 1 left until closing down connection Sep 25 23:16:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:17:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 0 left until closing down connection Sep 25 23:17:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 12 'Call-Clear-Request' Sep 25 23:17:41 Server syslog: pptp-client log[pptp_conn_close:pptp_ctrl.c:428]: Closing PPTP connection

Damit wäre meine Vermutung bestätigt, daß sich der pptp-client wegen fehlender echo replies beendet. Der nimmt einfach an, die Gegenstelle ist tot. Damit bin ich am Ende dessen, was ich tun kann, es scheint ein Problem auf der Inode Seite zu sein und es wäre schön, nochmal was von dieser Seite zu diesem Problem zu hören.

MfG,
Marvin

von **lahe** » Sa 25 Sep, 2004 23:26

marvin42 hat geschrieben:
lahe hat geschrieben:....schon wieder ein Log. Diesmal mit installiertem pptp-client von der fli4l Page mit loglevel 1
http://members.inode.at/b.aichberger/massages1.txt Zeit(UTC)

lahe

Die relevanten Teile:

Code: Alles auswählen
Sep 25 22:17:37 Server pppd[1945]: Local IP address changed to 83.64.199.231 Sep 25 22:17:37 Server pppd[1945]: Remote IP address changed to 62.99.171.97 Sep 25 22:17:37 Server pppd[1945]: sent [IP data] 45 00 00 39 f4 08 40 00 ... Sep 25 22:18:34 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 22:18:34 Server syslog: pptp-client log[logecho:pptp_ctrl.c:662]: Echo Reply received. ... Sep 25 23:11:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:11:41 Server syslog: pptp-client log[logecho:pptp_ctrl.c:662]: Echo Reply received. Sep 25 23:12:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:13:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 4 left until closing down connection Sep 25 23:13:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:14:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 3 left until closing down connection Sep 25 23:14:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:15:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 2 left until closing down connection Sep 25 23:15:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:16:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 1 left until closing down connection Sep 25 23:16:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:17:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 0 left until closing down connection Sep 25 23:17:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 12 'Call-Clear-Request' Sep 25 23:17:41 Server syslog: pptp-client log[pptp_conn_close:pptp_ctrl.c:428]: Closing PPTP connection

Damit wäre meine Vermutung bestätigt, daß sich der pptp-client wegen fehlender echo replies beendet. Der nimmt einfach an, die Gegenstelle ist tot. Damit bin ich am Ende dessen, was ich tun kann, es scheint ein Problem auf der Inode Seite zu sein und es wäre schön, nochmal was von dieser Seite zu diesem Problem zu hören.

MfG,
Marvin

Code: Alles auswählen: Sep 25 23:11:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:11:41 Server syslog: pptp-client log[logecho:pptp_ctrl.c:662]: Echo Reply received. Sep 25 23:11:43 Server kernel: fw-input-reject IN=ppp0 OUT= MAC= SRC=81.154.214.101 DST=83.64.199.231 LEN=47 TOS=0x00 PREC=0x00 TTL=116 ID=15538 PROTO=UDP SPT=6543 DPT=6346 LEN=27 Sep 25 23:11:48 Server kernel: fw-input-reject IN=ppp0 OUT= MAC= SRC=62.135.99.79 DST=83.64.199.231 LEN=46 TOS=0x00 PREC=0x00 TTL=113 ID=19578 PROTO=UDP SPT=3401 DPT=6346 LEN=26 Sep 25 23:11:54 Server kernel: fw-input-reject IN=ppp0 OUT= MAC= SRC=202.46.137.3 DST=83.64.199.231 LEN=47 TOS=0x00 PREC=0x00 TTL=111 ID=39841 PROTO=UDP SPT=13943 DPT=6346 LEN=27 Sep 25 23:12:00 Server kernel: fw-input-reject IN=ppp0 OUT= MAC= SRC=68.77.37.225 DST=83.64.199.231 LEN=46 TOS=0x00 PREC=0x00 TTL=112 ID=13909 PROTO=UDP SPT=18270 DPT=6346 LEN=26 Sep 25 23:12:06 Server kernel: fw-input-reject IN=ppp0 OUT= MAC= SRC=213.101.225.29 DST=83.64.199.231 LEN=47 TOS=0x00 PREC=0x00 TTL=117 ID=4459 PROTO=UDP SPT=1045 DPT=6346 LEN=27 Sep 25 23:12:12 Server kernel: fw-input-reject IN=ppp0 OUT= MAC= SRC=213.101.225.29 DST=83.64.199.231 LEN=47 TOS=0x00 PREC=0x00 TTL=117 ID=4849 PROTO=UDP SPT=1045 DPT=6346 LEN=27 Sep 25 23:12:19 Server kernel: fw-input-reject IN=ppp0 OUT= MAC= SRC=67.50.192.45 DST=83.64.199.231 LEN=47 TOS=0x00 PREC=0x00 TTL=107 ID=18290 PROTO=UDP SPT=6346 DPT=6346 LEN=27 Sep 25 23:12:39 Server kernel: fw-input-reject IN=eth1 OUT= MAC=00:50:fc:44:76:a2:00:a0:c5:81:5c:e6:08:00 SRC=10.202.0.1 DST=10.202.7.244 LEN=50 TOS=0x00 PREC=0x00 TTL=254 ID=46923 PROTO=ICMP TYPE=3 CODE=1 INCOMPLETE [30 bytes] Sep 25 23:12:40 Server kernel: fw-input-reject IN=eth1 OUT= MAC=01:00:5e:00:00:01:00:a0:c5:81:5c:e6:08:00 SRC=10.202.0.1 DST=224.0.0.1 LEN=28 TOS=0x00 PREC=0x00 TTL=1 ID=46951 PROTO=2 Sep 25 23:12:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:13:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 4 left until closing down connection Sep 25 23:13:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:14:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 3 left until closing down connection Sep 25 23:14:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:14:45 Server kernel: fw-input-reject IN=eth1 OUT= MAC=01:00:5e:00:00:01:00:a0:c5:81:5c:e6:08:00 SRC=10.202.0.1 DST=224.0.0.1 LEN=28 TOS=0x00 PREC=0x00 TTL=1 ID=47098 PROTO=2 [b]Sep 25 23:14:54 Server dropbear[3183]: Child connection from 192.168.0.5:3697[/b]Sep 25 23:14:55 Server dropbear[3183]: password auth succeeded for 'root' Sep 25 23:15:22 Server dropbear[3183]: exit after auth (root): Exited normally Sep 25 23:15:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 2 left until closing down connection Sep 25 23:15:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:16:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 1 left until closing down connection Sep 25 23:16:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 5 'Echo-Request' Sep 25 23:16:50 Server kernel: fw-input-reject IN=eth1 OUT= MAC=01:00:5e:00:00:01:00:a0:c5:81:5c:e6:08:00 SRC=10.202.0.1 DST=224.0.0.1 LEN=28 TOS=0x00 PREC=0x00 TTL=1 ID=47100 PROTO=2 Sep 25 23:17:41 Server syslog: pptp-client log[pptp_handle_timer:pptp_ctrl.c:1042]: missing echo reply, 0 left until closing down connection Sep 25 23:17:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 12 'Call-Clear-Request' Sep 25 23:17:41 Server syslog: pptp-client log[pptp_conn_close:pptp_ctrl.c:428]: Closing PPTP connection Sep 25 23:17:41 Server syslog: pptp-client log[ctrlp_rep:pptp_ctrl.c:246]: Sent control packet type is 3 'Stop-Control-Connection-Request' Sep 25 23:17:41 Server syslog: pptp-client log[call_callback:pptp_callmgr.c:77]: Closing connection Sep 25 23:17:41 Server pppd[1945]: Script pptp-client 10.0.0.138 --nolaunchpppd --sync --ignorebuffer --loglevel 1 --logstring pptp-client finished (pid 3049), status = 0x0

in der Zeit 23:12:40 bis zur nächsten Wiedereinwahl ging nichts mehr über die Leitung.
Wollte mir gerade ein Linux iso Downloaden als der Download auf 0,0KB zusammenbrach.
Hab mich gewundert warum das so war und mich mit putty auf dem Router eingeloggt.

von **dfx** » Sa 25 Sep, 2004 23:46

so macht debuggen spaß

utc sind die zeiten aber nicht, oder? weil du um 23:00 ein log mit timestamps 23:30 postest (was dann außerdem 01:30 wäre)...

aber egal. hier ist die connection tatsächlich "eingeschlafen" und war dann sogar etwas länger weg (erster wiedereinwahlversuch nach dem disconnect ist ja fehlgeschlagen).

ich nehme mal an, daß da grade die dsl leitung geflogen ist. genau zuordnen kann mans wegen der falschen timestamps nicht, aber laut log war die leitung um 22:54 kurz weg. und wenn's dsl weg is, dann hält sich auch kein pptp-tunnel...

von **lahe** » Sa 25 Sep, 2004 23:54

dfx hat geschrieben:
genau zuordnen kann mans wegen der falschen timestamps nicht, ...

02:06:50 Zeit vom Router
01:07:38 Zeit vom lokalem Lan (Timeserver (Eisfair jede 1/2 Stunde))

also, wenn ich mich nicht verrechnet habe geht die Uhrzeit vom Router um 00:59:12 vor

lahe

von **dfx** » So 26 Sep, 2004 01:39

lahe hat geschrieben:also, wenn ich mich nicht verrechnet habe geht die Uhrzeit vom Router um 00:59:12 vor

da stimmt einiges nicht... der router zeigt als zeitzone "+0200" an, was die richtige lokale zeitzone wäre (CEST, mitteleuropäische sommerzeit), aber mit der falschen uhrzeit: du hast laut xDSL.at um 00:54 gepostet, nicht um 02:06 (und die xDSL.at timestamps stimmen).

dein rechner ist auf "westeuropäische normalzeit" gestellt, was aber nicht utc ist. zwischen utc und cest liegen 2 stunden, nicht eine; und zwischen utc und westeuropäischer zeit liegen im moment (wegen sommerzeit) eine stunde. außerdem müßte die uhr dann gegenüber lokaler zeit _nach_ gehen, nicht vor. also zeitpunkt deines postings (00:54) wäre in utc 22:54.

deswegen trau ich den timestamps in dem log nicht.

</nitpicking type="extrem">

von **lahe** » So 26 Sep, 2004 11:39

..so, jetzt laufen bei mir alle Uhren nach ntps1-1.uni-erlangen.de

lahe :banghead:

von **lahe** » So 26 Sep, 2004 19:21

Es war wieder mal soweit. Die Verbindung wurde um

18:57:47 um
19:35:59 und um
20:11:17 nach 8,1min :conspiration:

getrennt.

Log: http://members.inode.at/b.aichberger/lo ... evel_2.txt

@dfx: diesmal stimmen die Zeiten der Logdateien !
kannst Du dir das bitte mal ansehen!

Danke
lahe

von **dfx** » So 26 Sep, 2004 19:33

lahe hat geschrieben:18:57:47 um
19:35:59 und um
20:11:17 nach 8,1min getrennt.

jup, da hat's jeweils die dsl-leitung gebirnt (ca 5 minuten isses daneben):

Code: Alles auswählen: Sep 26 18:51:53 172.16.29.7 ZyXEL: port 7, C02 ADSL Disconnected (SN=125) Sep 26 18:52:16 172.16.29.7 ZyXEL: port 7, C01 ADSL Connected (SN=126) 384/2560 Kbps Sep 26 19:30:11 172.16.29.7 ZyXEL: port 7, C02 ADSL Disconnected (SN=126) Sep 26 19:30:35 172.16.29.7 ZyXEL: port 7, C01 ADSL Connected (SN=127) 384/2560 Kbps Sep 26 19:57:39 172.16.29.7 ZyXEL: port 7, C02 ADSL Disconnected (SN=127) Sep 26 19:58:02 172.16.29.7 ZyXEL: port 7, C01 ADSL Connected (SN=128) 384/2560 Kbps Sep 26 20:06:06 172.16.29.7 ZyXEL: port 7, C02 ADSL Disconnected (SN=128) Sep 26 20:06:29 172.16.29.7 ZyXEL: port 7, C01 ADSL Connected (SN=129) 384/2560 Kbps

ich sehe, du hast mal nen neuen p650 gekriegt, wegen eben solchen problemen. war's vorher noch schlimmer oder hat sich's doch gebessert?

gab's wegen dieser probleme jetzt schon mal ne störungsmeldung von deiner seite?

von **lahe** » So 26 Sep, 2004 19:53

.. und jetzt hat er gerade wieder getrennt.
Habe den Log im vorhergehenden Posting aktualisiert.

ich sehe, du hast mal nen neuen p650 gekriegt, wegen eben solchen problemen. war's vorher noch schlimmer oder hat sich's doch gebessert?

gab's wegen dieser probleme jetzt schon mal ne störungsmeldung von deiner seite?

Den p650 Tausch hat Andreas Granig veranlaßt, da ich ständige Probleme mit Voip hatte und habe.
siehe Posting: http://xDSL.at/phpbb2/viewtopic.php?p=1 ... ht=#157390

Es hat dann einige Tage funktioniert und die Verbindungsabbrüche waren aber schon immer, aber nicht in diesen kurzen Abständen.
Eine Störmeldung gab es in diesem Zusammenhang noch keine.
Habe zwar einige male angerufen, die sagten aber immer nur ich soll mein Modem bzw den Ata ausschalten.

Habe meine Anliegen bisher hier gepostet !

Danke

lahe

xDSL.at

automatische Verbindungstrennung bei Inode, Problem VoIP ?!?

Wer ist online?