Probleme mit itelex-Verbindungsabbrüchen

[ulbrichf]

Hallo Kilian,
wollte Dir ein TELEX schicken, scheinst aber nicht online zu sein.
Der Firmware Test mit Version 636 fände ich sehr interessant.
Ich kann Dir gerne die HEX Datei per email senden, damit Du nicht suchen mußt.
Die 10 Tage Wettervorhersage unter iTELEX 727272 ist ähnlich lang.
MfG
Frank

[FredSonnenrein]

...ich denke ich muss mal ein paar Worte zum Thema Absturz generell loswerden. Wird aber lang:

System-Struktur und Resets
Zunächst eine kurze Erläterung über die Software-Struktur des i-Telex. Ich werwende ein Grundprojekt namens "OpenMCP".
Das Projekt enthält bereits alles was ich an "Betriebssystem" brauche. Netzwerk-Protokolle TCP und UDP, CGI-Formular-Bearbeitung,
Uhr, kooperatives Multitasking, Interupt-Bearbeitung.
Der Code von mir zur Funktion des i-Telex hat daher hauptsächlich nur zwei große Teile:
1. Die Funktion "itelex_thread": Diese wird vom Betriebssystem regelmäßig aufgerufen. Da beim kooperativen Multitasking
die Gesamtfunktion des Systems darauf angewiesen ist, dass der Task auch mal den Programmfluss an andere Tasks übergibt, enthält
die Funktion "itelex_thread" so gut wie keine Schleifen, sondern verlässt sich darauf eben regelmäßig aufgerufen zu werden.
Den Takt des Aufrufs kann man aber nicht vorhersagen.
2. Die Funktion "itelex_timerEvent": Diese Funktion wird alle 2 Millisekunden per Timer-Interrupt aufgerufen, in erster Linie um
zeitgerecht die Umwandlung des 50-Baud-Signals zu bearbeiten.

Zur Überwachung, dass das System nicht irgenwo hängt, sind zwei Schutzfunktionen eingebaut.
a) In der Funktion "itelex_timerEvent" wird der "Watchdog" zurückgesetzt. Dieser Watchdog ist eine Hardware-Komponente im
Prozessor, die einen Reset auslöst, wenn das erwähnte Rücksetzen des Watchdog über eine gewisse Zeitspanne
(hier 4 SSekunden) nicht erfolgt. So ist also sichergestellt, dass "itelex_timerEvent" nicht "vergessen" wird.
b) In "itelex_timerEvent" wird kontrolliert, dass auch die Funktion "itelex_thread" regelmäßig aufgerufen wird.
Dazu ist eine Software-Stoppuhr eingebaut. Diese wird von "itelex_thread" auf Null gesetzt und in "itelex_timerEvent"
kontrolliert: Bei 0,5 sekunden wird die rote LED angemacht, bei 90 sekunden ein Reset ausgelöst.

Wenn nun eine i-Telex-Station einen Neustart macht, kann das somit drei grundsätzliche "Grundursachen" haben:
x) Irgend ein Interrupt blockiert die Systemfunktion. Dann schlägt der Watchdog nach 4 Sekunden zu und
startet das System neu.
y) Irgend eine "normale" Funktion blockiert das Multitasking. Dann leuchtet 90 sekunden lang die rote LED und
danach startet das System neu.
z) Irgedwie "verirrt" sich das Programm komplett (Musterbeispiel: Durch falsche Speicherzugriffe ist der Stack
nicht mehr korrekt und der Rücksprung aus einem Unterprogramm landet sonstwo). Dann landet die
Programausführung mehr oder weniger zufällig auch meist beim Reset.

Verhalten bei Verbindungsabbrüchen
Völlig unabhängig von irgendwelchen Absturzproblemen erkannte ich schnell, dass doch recht häufig die
TCP-Verbindung während der Kommunikation zwischen zwei i-Telexen unterbrochen wird. Daher sind
folgende Algorithmen vorhaden.
1. Wenn eine Station absichtlich die Verbindung abbaut, dann wird ein Ende-Datentelegramm gesendet.
Daraufhin weiß die Gegenstelle, dass ein "Abriss" der Kommunikation tatsächlich beabsichtigt ist und
schaltet den Fernschreiber dann auch aus.
2. Wenn ein Verbindungsabriss eintritt, ohne dass dieses Ende-Datentelegramm vorher empfangen
wurde, dann versucht die i-Telex-Station beim Anrufer selbsttätig die angerufenen Station wieder
zu erreichen. Gelingt dass innerhalb von 30 Sekunden wird weitergemacht, als wäre nichts gewesen.
Gelingt dies nicht, wird dann der Fernschreiber abgeschaltet.

Zusammenspiel von Reset und der oben erläuterten Strategie der Verbindungswiederherstellung
Die beiden oben beschriebenen Prinzipien führen nun zu folgenden Verhalten, wenn eine Station einen
Reset macht:
Reset beim Anrufer: Hierbei "vergisst" die Anrufende Station natürlich die eben noch bestehende
Verbindung, somit erfolgt kein automatischer Versuch des Wiederaufbaus.
Schafft es der Anrufer aber, innerhalb der 30 Sekunden den angerufenen wieder zu erreichen, dann
"glaubt" die angerufene Station, dass dies ein "normaler" Wiederaufbau war. Die folge ist, dass
von der angerufenen Stelle nicht das Datum gedruckt wird.
Reset beim Angerufenen: Sofern dieser Neustart schnell genug ist, "glaubt" die anrufende
Station, dass es sich um eine normale vorübergehende Verbindungsstörung handelt und schreibt
den zwischengespeicherten Text fleißig an den angerufenen.
Dort aber erscheint dieses Schreiben des zwischengespeicherten Textes wie ein neuer Anruf
mit folgenden Folgen: Das Datum wird gedruckt und der Anruf landet auf der Hauptstelle des
Systems, da die Nebenstellen-Durchwahl nur ein mal am Anfang der Verbindung übermittelt wird.

OCC-Meldung mitten im Text
Das von Kilian erstmalig entdeckte Problem, dass mitten im Text ein "occ" gedruckt wird, ist
wahrscheinlich wie folgt verursacht.
Kilians Station bemerkt einen Abbruch der Verbindung und schafft es recht schnell, die Gegenstelle
wieder zu erreichen. Die Gegenstelle hat aber den Verbindungsabbruch noch gar nicht bemerkt und
"glaubt" dass der Wiederholungsanruf von Kilian ein zweiter Anrufer ist. Daher sendet die Gegenstelle
das übliche Besetzt an den zweiten Anrufer, der aber gar nicht ein zweiter Anrufer ist.

Fazit
Puh. Wer hat das alles verstanden?
Ich hoffe, dass die scheinbar "wirren" Reaktionen des Systems ein bischen klarer geworden sind.

[Helge]

Hallo Fred,

danke, die Nebel lichten sich. Gibt es eine Übersicht über die Resetgründe?

z.B. "SystemStartZeit = 19.11.2016 17:50:11, ResetFlag = 08"

[FredSonnenrein]

ResetFlag:
Bit 4: Reset durch JTAG-Schnittstelle (kann nicht vorkommen)
Bit 3: Reset durch Watchdog (da es keinen Reset-Assembler-Befehl gibt wird ein absichtlicher Reset dadurch gelöst, dass man den Watchdog ablaufen lässt)
Bit 2: Brown-Out Reset: Versorgungsspannung war zu gering
Bit 1: External Reset: Kommt nicht vor, da der externe Reset-Eingang nur von der Programmier-Schnittstelle "bearbeitet" wird.
Bit 0: Power-On Reset: Versorgungsspannung wurde erstmals angelegt.

Also ist 08 der Standard-Fall für einen Software-Reset, 05 oder 01 für einen Reset durch abschalten und wieder Einschalten der Spannungsversorgung.

[Martin]

Mich würde mal interessieren was an der 666er Version so viel anders ist.
Die läuft lt. meiner Ansicht sogar noch stabiler als die 573 die Henning bisher noch ausgeliefert hat.
Abstürze habe ich im Durchschnitt etwa alle 20 Tag 1 X. Das ist ok dafür das mein System mit 2 i-Telexkarten rund um die Uhr läuft.

[Alex]

Meine 666 läuft auch schon seit über einem Monat absturzfrei. Keine Ahnung warum die bei manchen so Probleme macht.
SystemStartZeit = 26.10.2016 23:33:18, ResetFlag = 05

[380170JFK]

Wer hat eigentlich behauptet es sei "Schuld" der Firmware ........ es ist hier (fast ein Einzelfall) das seitens Kilian die Verbindung kurz wegfallt.
Beim letzten Versuch war das nur 3 Sekunden (Protokolliert im T-Manager von Telekom) , um dann die Verbindung seitens Kilian wieder auf zu bauen. Da kann durchaus seine DSL (Provider Router Hub usw) mit ins Spiel sein statt die Firmware
Er sollte auch mal seine Versorgungsspannung dauerhaft messen, dann ist es wieder etwas eingegrenzt (Reset der i-Telex Karte)

[Martin]

Tach auch,
habe gerade beim Chat mit Helge folgendes beobachten können:

Kein Absturz, weder bei ihm noch bei mir.
Feste IP bei mir, kein Wechsel bei ihm, da während der Zeit auch noch ein VPN-Tunnel bestand, der hätte ja dann mal ausfallen müssen.
Verbindung abgerissen mit Meldung OCC bei mir.

► Text anzeigen

Letzter Anruf: 25.11.2016 21:29:09
DiagnosePuffer: 25.11.2016 21:52:59 kommender Anruf abgewiesen wegen besetzt
DiagnosePufferLevel = 4
Teilnehmer-Server inaktiv
TeilnehmerServerAlleNichtErreichbar = 0
AktTlnServerTabI = 0
TeilnehmerServerFehlerZaehler(df3oe.no-ip.org) = 0, Sperre-Timer 341
TeilnehmerServerFehlerZaehler(sonnibs.no-ip.org) = 0, Sperre-Timer 742
TeilnehmerServerFehlerZaehler(176.52.197.242) = 0, Sperre-Timer 742
Modus = 0
Status = A0
BusEmpfMark = 1
SerUmTickZaehlerEmpf = 10
SerUmEmpfBitNr = 0
SerUmEmpfMarkZaehl = 0
SerUmEmpfDaten = 8
SerUmEmpfFehler = 0
PufferAnzahl(&EmpfPuffer) = 0
SendeMark = 1
SerUmTickZaehlerSend = 14
SerUmSendBitNr = 0
SerUmSendDaten = 192
PufferAnzahl(&SendePuffer) = 0
Wahlnummer = 52490
Wahlziffern = 6
KurzTimerVal(&WahlPauseTimer) = 9671
KurzTimerVal(&SchreibPauseTimer) = 13773
DynIP_Phase = 3
LangTimerVal(&DynIPAktualisierungTimer) = 341
DynIPAktualisierungEndzeit = 346
SelbstAnrufPhase = 0
SelbstAnrufFehlerZaehler = 0
KurzTimerVal(&SelbstAnrufTimer) = 3
SelbstAnrufEndzeit = 4451
SelbstAnrufSocketHandle = -1
SelbstAnrufSendePruefwert = 55563
SelbstAnrufEmpfangPruefwert = 55563
SelbstAnrufZeitUeberwachung: Summe/Anz = 4623/88 Max = 101 AnzUeberGrenze = 3
iTelexSocketMode = 0
iTelexSocketHandle = -1
iTelexSocketIP = 00
iTelexSocketPort = 134
iTelexSocketProtokoll = 0
iTelexSocketProtVersion = 0
iTelexSocketAbbauGeplant = 0
KurzTimerVal(&iTelexSocketAbbruchTimer) = 10293
SocketInBufUsed = 0
SocketOutBufUsed = 0
ProtokollPhase = 0
SocketAnzahlZeichenGesendet = 0
SocketAnzahlZeichenQuittiert = 0
SocketAnzahlZeichenEmpfangen = 0
TeilnehmerServerSocket = -1
HtmlSendeText: []
AsciiDruckPuffer: []
LangTimerVal(&BeideRuhigTimer) = 8
KurzTimerVal(&BusQuittTimer) = 5522
TwiLebenszeichenZaehler = 239
TwiWatchdogCount = 26943
BusKollisionZaehler = 2
KurzTimerVal(&iTelexSocketLebenszeichenTimer) = 11664
KurzTimerVal(&ITelexThreadCheckTimer) = 5
FalscherCode = 0
TwiIsrCount = 22443
ITelexThreadCount = 1810
Timer0CallbackCount = 40273
Timer0Cnt_Min = 0
Timer0Cnt_Max = 125
Timer0Callback_Max = 132
TCP_socket[0]: ConnectionState=16, SendState=0, SourcePort=56278, DestinationPort=80, SourceIP=28B2A80A, Timeoutcounter=30
TCP_socket[1]: closed
TCP_socket[2]: closed
TCP_socket[3]: closed
TCP_socket[4]: closed
TCP_socket[5]: closed
NetzPort = 134
NetzEigeneIP = EC5D
LangTimerVal(&ZeitServerAbfrageTimer) = 742
ZeitServerAbfrageTimerEnde = 8280
NTPUpdateDiffSeconds = 0
Debug_LowestSP = 189A
XMCRA = 85
SystemStartZeit = 25.11.2016 19:49:30, ResetFlag = 08
VCC [mV] = 5073 5028 5073 5096 5073 5096 5073 5073 5028 5096
Statiktik-Daten zurücksetzen
Ethernet: 4813791 Bytes in 65324 Packeten LockErrors 0

► Text anzeigen

Letzter Anruf: 25.11.2016 21:29:09
DiagnosePuffer:
DiagnosePufferLevel = 0
Teilnehmer-Server inaktiv
TeilnehmerServerAlleNichtErreichbar = 0
AktTlnServerTabI = 0
TeilnehmerServerFehlerZaehler(df3oe.no-ip.org) = 0, Sperre-Timer 8
TeilnehmerServerFehlerZaehler(sonnibs.no-ip.org) = 0, Sperre-Timer 787
TeilnehmerServerFehlerZaehler(176.52.197.242) = 0, Sperre-Timer 787
Modus = 0
Status = A0
BusEmpfMark = 1
SerUmTickZaehlerEmpf = 10
SerUmEmpfBitNr = 0
SerUmEmpfMarkZaehl = 0
SerUmEmpfDaten = 0
SerUmEmpfFehler = 0
PufferAnzahl(&EmpfPuffer) = 0
SendeMark = 1
SerUmTickZaehlerSend = 0
SerUmSendBitNr = 0
SerUmSendDaten = 192
PufferAnzahl(&SendePuffer) = 0
Wahlnummer = 35492
Wahlziffern = 6
KurzTimerVal(&WahlPauseTimer) = 40219
KurzTimerVal(&SchreibPauseTimer) = 7804
DynIP_Phase = 3
LangTimerVal(&DynIPAktualisierungTimer) = 8
DynIPAktualisierungEndzeit = 324
SelbstAnrufPhase = 0
SelbstAnrufFehlerZaehler = 0
KurzTimerVal(&SelbstAnrufTimer) = 3077
SelbstAnrufEndzeit = 4481
SelbstAnrufSocketHandle = -1
SelbstAnrufSendePruefwert = 28312
SelbstAnrufEmpfangPruefwert = 28312
SelbstAnrufZeitUeberwachung: Summe/Anz = 4656/89 Max = 101 AnzUeberGrenze = 3
iTelexSocketMode = 0
iTelexSocketHandle = -1
iTelexSocketIP = 00
iTelexSocketPort = 134
iTelexSocketProtokoll = 1
iTelexSocketProtVersion = 0
iTelexSocketAbbauGeplant = 0
KurzTimerVal(&iTelexSocketAbbruchTimer) = 3081
SocketInBufUsed = 0
SocketOutBufUsed = 0
ProtokollPhase = 0
SocketAnzahlZeichenGesendet = 0
SocketAnzahlZeichenQuittiert = 0
SocketAnzahlZeichenEmpfangen = 0
TeilnehmerServerSocket = -1
HtmlSendeText: []
AsciiDruckPuffer: []
LangTimerVal(&BeideRuhigTimer) = 8
KurzTimerVal(&BusQuittTimer) = 50661
TwiLebenszeichenZaehler = 161
TwiWatchdogCount = 15401
BusKollisionZaehler = 2
KurzTimerVal(&iTelexSocketLebenszeichenTimer) = 3082
KurzTimerVal(&ITelexThreadCheckTimer) = 6
FalscherCode = 0
TwiIsrCount = 41054
ITelexThreadCount = 47653
Timer0CallbackCount = 3826
Timer0Cnt_Min = 0
Timer0Cnt_Max = 125
Timer0Callback_Max = 132
TCP_socket[0]: ConnectionState=16, SendState=0, SourcePort=56290, DestinationPort=80, SourceIP=28B2A80A, Timeoutcounter=30
TCP_socket[1]: closed
TCP_socket[2]: closed
TCP_socket[3]: closed
TCP_socket[4]: closed
TCP_socket[5]: closed
NetzPort = 134
NetzEigeneIP = EC5D
LangTimerVal(&ZeitServerAbfrageTimer) = 787
ZeitServerAbfrageTimerEnde = 8280
NTPUpdateDiffSeconds = 0
Debug_LowestSP = 189A
XMCRA = 85
SystemStartZeit = 25.11.2016 19:49:30, ResetFlag = 08
VCC [mV] = 5073 5096 5073 5096 5073 5073 5096 5073 5096 5073
Statiktik-Daten zurücksetzen
Ethernet: 5276836 Bytes in 71616 Packeten LockErrors 0

► Text anzeigen

Letzter Anruf: 25.11.2016 21:55:01
DiagnosePuffer:
DiagnosePufferLevel = 0
TlnServSyncStichzeit(sonnibs.no-ip.org) = 25.11.2016 18:49:59
TlnServSyncStichzeit(120.146.186.6) = 17.11.2016 19:23:13
TlnServSyncStichzeit(df3oe.no-ip.org) = 25.11.2016 18:53:00
TlnServerKanal 0 wurde 907 mal genutzt.
TlnServerKanal 1 wurde 5 mal genutzt.
TlnServerKanal 2 wurde 0 mal genutzt.
TlnServerKanal 3 wurde 0 mal genutzt.
TlnBuchLetzteAenderung = 25.11.2016 18:49:58
KurzTimerVal(&SyncWarteTimer) = 9600
SyncWarteEnde = 2400
LangTimerVal(&VollAbfrageTimer) = 2797
VollAbfrageTimerEnde = 9000
VollAbfrageServerIndex = 1
TeilnehmerServerAlleNichtErreichbar = 0
AktTlnServerTabI = 0
TeilnehmerServerFehlerZaehler(sonnibs.no-ip.org) = 0, Sperre-Timer 2805
TeilnehmerServerFehlerZaehler(120.146.186.6) = 12, Sperre-Timer 681
TeilnehmerServerFehlerZaehler(df3oe.no-ip.org) = 0, Sperre-Timer 1780
Modus = 0
Status = A0
BusEmpfMark = 1
SerUmTickZaehlerEmpf = 10
SerUmEmpfBitNr = 0
SerUmEmpfMarkZaehl = 0
SerUmEmpfDaten = 19
SerUmEmpfFehler = 0
PufferAnzahl(&EmpfPuffer) = 0
SendeMark = 1
SerUmTickZaehlerSend = 14
SerUmSendBitNr = 0
SerUmSendDaten = 192
PufferAnzahl(&SendePuffer) = 0
Wahlnummer = 61001
Wahlziffern = 5
KurzTimerVal(&WahlPauseTimer) = 31008
KurzTimerVal(&SchreibPauseTimer) = 13491
DynIP_Phase = 0
LangTimerVal(&DynIPAktualisierungTimer) = 3719
DynIPAktualisierungEndzeit = 3
SelbstAnrufPhase = 3
SelbstAnrufFehlerZaehler = 0
KurzTimerVal(&SelbstAnrufTimer) = 9271
SelbstAnrufEndzeit = 0
SelbstAnrufSocketHandle = -1
SelbstAnrufSendePruefwert = 0
SelbstAnrufEmpfangPruefwert = 0
SelbstAnrufZeitUeberwachung: Summe/Anz = 0/0 Max = 0 AnzUeberGrenze = 0
iTelexSocketMode = 0
iTelexSocketHandle = -1
iTelexSocketIP = 00
iTelexSocketPort = 134
iTelexSocketProtokoll = 0
iTelexSocketProtVersion = 0
iTelexSocketAbbauGeplant = 0
KurzTimerVal(&iTelexSocketAbbruchTimer) = 9273
SocketInBufUsed = 0
SocketOutBufUsed = 0
ProtokollPhase = 0
SocketAnzahlZeichenGesendet = 402
SocketAnzahlZeichenQuittiert = 146
SocketAnzahlZeichenEmpfangen = 436
TeilnehmerServerSocket = -1
HtmlSendeText: []
AsciiDruckPuffer: []
LangTimerVal(&BeideRuhigTimer) = 664
KurzTimerVal(&BusQuittTimer) = 9439
TwiLebenszeichenZaehler = 233
TwiWatchdogCount = 46371
BusKollisionZaehler = 0
KurzTimerVal(&iTelexSocketLebenszeichenTimer) = 9705
KurzTimerVal(&ITelexThreadCheckTimer) = 29
FalscherCode = 0
TwiIsrCount = 16391
ITelexThreadCount = 45995
Timer0CallbackCount = 53070
Timer0Cnt_Min = 0
Timer0Cnt_Max = 125
Timer0Callback_Max = 132
TCP_socket[0]: closed
TCP_socket[1]: ConnectionState=16, SendState=0, SourcePort=2370, DestinationPort=80, SourceIP=301A8C0, Timeoutcounter=30
TCP_socket[2]: closed
TCP_socket[3]: closed
TCP_socket[4]: closed
TCP_socket[5]: closed
NetzPort = 134
NetzEigeneIP = 00
LangTimerVal(&ZeitServerAbfrageTimer) = 487
ZeitServerAbfrageTimerEnde = 8640
NTPUpdateDiffSeconds = 4
Debug_LowestSP = 1898
XMCRA = 85
SystemStartZeit = 17.11.2016 21:57:09, ResetFlag = 08
VCC [mV] = 5166 5120 5096 5143 5166 5120 5096 5143 5143 5166
Statiktik-Daten zurücksetzen
Ethernet: 45720745 Bytes in 534291 Packeten LockErrors 0

!	Nachricht von: Alex
	Riesige Textblöcke der Übersichtlichkeit wegen bitte in Spoiler-Tags einbetten

[Helge]

Hi,

das die Daten zur Internetverbindung:

25.11.16
09:24:54
Internetverbindung wurde erfolgreich hergestellt. IP-Adresse: 93.236.48.217, DNS-Server: 217.237.150.188 und 217.237.151.142, Gateway: 62.155.245.205, Breitband-PoP: REUJ01
25.11.16
09:24:54
Information des Anbieters über die reale Bandbreite: 102784/20000 kbit/s

Da gab es in der fraglichen Zeit keine IP-Neuvergabe.

[FredSonnenrein]

Durch welche Umstände ein OCC mittendrin entsteht, hatte ich ha schon mal erwähnt. Könnte ich vielleicht sogar "wegprogrammieren", das i-Telex muss nach dem Verbindungsabriß einfach nur wenige Sekunden warten, so dass die Gegenstelle auch "garantiert" den Abriß mitbekommen hat.

Unterschied zwischen 666 und 573: Ganz einfach: 93
Im Ernst: Ein paar Bug-Fixes und die Option, Software-Updates der anderen Karten des i-Telex machen zu können (man muss nur ein Spezialkabel basteln).