Bug im FritzBox Binding?

[Jockel]

Hallo zusammen,

ich nutze das Fritzbox Binding um auf eingehende Telefonate zu triggern. In der entsprechenden Regel lese ich die Rufnummern aus, wie hier ja schon an anderer Stelle gepostet:

var call = Call_Incoming_No.state as CallType
var destNum = call.getDestNum()
var origNum = call.getOrigNum()

Diese Nummern benutze ich in einer Regel und logge sie gleichzeitig. Das hat sowei auch gut funktioniert, allerdings gibt es seit zwei Tagen Probleme beim Auslesen der Nummern, sie werden nicht mehr geloggt (der String ist leer) und auch die Abfrage darauf funktioniert damit nicht mehr. Das FritzboxBinding erkennt aber weiterhin das ein Anruf eingeht. Nach dem letzten sauberen Start von openHAB hat alles wie gewünscht funktioniert, danach hab ich keine Items oder Regeln mehr verändert.

Getestet hab ich dann folgendes:
1. Telnet auf den Monitoring Port der Fritzbox: Die Fritzbox gibt die Anrufe komplett und richtig aus, openHAB erkennt den eingehenden Anruf aber nicht die Nummer

2. Neustart von openHAB, alle Regeln und Items unverändert: Alles funktioniert wieder wie gewünscht.

Vielleicht hat das ja auch schon jemand anderes beobachtet?

Viele Grüße,
Jockel

[Jockel]

Nachdem ich eben das gleiche Verhalten wieder aufgetreten ist, habe ich den verdacht das es durch Anrufe von der Mobotix per SIP an die Fritzbox ausgelöst wird. Ev. stören die Sonderzeichen in der Übertragenen Rufnummer?

01.02.13 21:09:19;RING;2;***11#*#*90;12;ISDN;

[teichsta]

Hi,

Ev. stören die Sonderzeichen in der Übertragenen Rufnummer?

an sich eine gute Idee, allerdings wird der Inhalt des Feldes, dass die Rufnummer enthält komplett als String behandelt und ich finde keinen Hinweis auf ein spezielles Verhalten für Sonderzeichen ...

Da ich das Binding selbst nicht nutze, hoffe ich auf andere Supporter/Beobachter :-)

Gruß,

Thomas E.-E.

[Jockel]

Ich hab eben noch mal etwas getestet und es scheint in der Tat an den intenen Anrufen der Mobotix über den SIP-Provider der Fritzbox zu liegen. Das ganze sieht im Monitor der Fritzbox folgendermaßen aus:

01.02.13 21:09:19;CALL;1;20;90;91#;ISDN;
01.02.13 21:09:19;RING;2;***11#*#*90;12;ISDN;
01.02.13 21:09:27;DISCONNECT;2;0;
01.02.13 21:09:27;CONNECT;1;20;91#;
01.02.13 21:09:29;DISCONNECT;1;3;

Auf den ersten Blick sehe ich im Code auch keine Ursache dafür. Erstaunlich ist ja auch, dass selbst nachfolgende Anrufe dann zwar noch erkannt werden, aber eben nur noch ohne Rufnummer.

Ev. liegt der Bug dann auch nicht im Fritzbox-Binding selbst, dass legt ja bei jedem Anruf neue CallType Objekte an sondern irgendwo tiefer im Item Umfeld, denn das Item bleibt ja für alle Anrufe gleich?

[Jockel]

Nur so ein Gedanke, bei dem # kommt einem ja die format() Funktion für Strings in den Sinn, vielleicht aber auch die falsche Ecke?!

[Jockel]

So, ich hab mal angefangen das ganze ein wenig zu Debuggen, bislang leider ohne Erfolg.

Um nicht meine Produktivumgebung nutzen zu müssen habe ich den aktuellen Trunk genommen und die IDE installiert wie im Wiki beschrieben. Die Fritbox simuliere ich per netcat (nc -l 1012), wo ich den Mitschnitt aus einer Telnetsitzung zeilenweise hineinkopiere. Funktioniert so weit gut.

Leider kann ich den Fehler damit aber nicht reproduzieren, an den Sonderzeichen in den Rufnummern scheint es jedenfalls nicht zu liegen oder zumindest nicht alleine. Im Repository scheint es auch keine für das Problem relevanten Änderungen gegenüber meiner Produktivversion zu geben. Dort kann ich die sporadischen Ausfälle aber weiter beobachten.

Das FritzBox Binding reagiert zwar etwas allergisch auf unerwartete Eingaben, das ist im realen Betrieb aber wahrscheinlich kein Problem.

Ich bin gerne bereit da weiter zu suchen, aber für alle Ideen zur Ursache dankbar!

[Jockel]

Ich habe des ganze jetzt noch mal etwas beobachtet und glaube eigentlich nicht mehr an einen Bug im Binding oder der internen Verarbeitung auf dem openHAB Bus. Starkes Indiz dafür ist auch, das die Nummern im event.log immer korrekt angezeigt werden.

Trotzdem reagiert meine Regel irgendwann nicht mehr auf Nummern und loggt anstatt der Nummer nur noch leere Strings. Vielleicht habe ich da ja auch noch einen Bug, ich hab sie unten noch mal angefügt.

Wobei ich inzwischen aber einen Bug im Variablen-Handling von Xbase für wahrscheinlich halte, das würde auch andere Merkwürdigkeiten erklären, die ich in letzter Zeit beobachtet habe.

Hier aber noch mal meine Regel.

import org.openhab.core.library.types.*
import org.openhab.library.tel.types.*
import java.util.Calendar
import java.util.Date
import java.util.TimeZone


rule "Incoming call detected"
when
	Item Call_Incoming changed to ON
then	
	var CallType call = Call_Incoming_No.state as CallType
	var String destNum = call.getDestNum().toString()
	var String origNum = call.getOrigNum().toString
		
	logInfo("fritzbox rules", "Incomming call detected: " + origNum + " to " + destNum)
	
	if (origNum.contains("1234") && destNum.equals("567")) {
                 sendCommand(Network_OPENVPN_Server, ON)
             }  	
end

Im Fehlerfall sieht die Log-Meldung dann folgendermaßen aus, während die Nummer im Event-Log korrekt aufgeführt wird:

2013-02-11 13:33:21.298 INFO  o.o.m.script.fritzbox rules[:73]- Incomming call detected:  to

[Jockel]

Es gibt neue Erkenntnisse.

Inzwischen kann ich meinen Fehler in dem oben geposteten Test-Setup zuverlässig reproduzieren, wenn ich dem Netcat Server per cat einen Mitschnitt der Fritzbox Ausgaben vorsetze und diese so an openHAB weiterreiche (cat test.txt | nc -l 1012).

Dazu hab ich vor dem Verbindungsaufbau einen Breakpoint gesetetzt, starte dann den das Netcat und setze danach openHAB fort. Das klappt zuverlässig.

Dabei hat sich gezeigt, das das Fritzbox Binding die Daten zuverlässig auswertet und sie auch korrekt auf den Bus gepostet werden.

Da ich den Fehler beim Zeilenweisen einfügen der Daten nicht reproduzieren konnte hab ich dann testweise im Fritzbox Binding vor dem Verarbeiten der einzelnen von der Fritzbox gelesenen Zeilen ein sleep eingebaut. Sieht dann ab Zeile 252 so aus:

if(line!=null) {
    MonitorEvent event = parseMonitorEvent(line);
    processMonitorEvent(event);
    try {
        sleep(100L);
    } catch (InterruptedException e) {
    }
}

Damit funktioniert zumindest bei meinen ersten Tests zuverlässig und die Nummern werden in der Regel korrekt erkannt und ausgegeben.

Das bringt mich zu der Vermutung, dass es es ev. irgendwo eine Race-Condition gibt oder aber die Regeln ev. nicht Reentrant sind.

Das würde sich übrigens auch mit meiner Beobachtung, dass der Fehler bei Anrufen meiner T24 auftritt decken, da kommt es zu Ereignissen die unmittelbar hintereinander auftreten.

[kkreuzer]

Das ist spannend. Ja, klingt durchaus so, als ob die Rules hier nicht reentrant-fähig sind. Vom Code her sollte man nicht erwarten, dass die Variablen plötzlich wieder ungesetzt sind. Vielleicht ist das sogar ein Bug in Xbase...? Habe nicht wirklich die Muße da rein zu tauchen, vielleicht ist Dein 100ms Sleep ja ein ganz valider Workaround...?

Grüße,
Kai

[Jockel]

Das ist spannend. Ja, klingt durchaus so, als ob die Rules hier nicht reentrant-fähig sind. Vom Code her sollte man nicht erwarten, dass die Variablen plötzlich wieder ungesetzt sind. Vielleicht ist das sogar ein Bug in Xbase...? Habe nicht wirklich die Muße da rein zu tauchen, vielleicht ist Dein 100ms Sleep ja ein ganz valider Workaround...?

Ich glaube da auch an einen Bug im xbase, dass hatte ich ja auch schon bei anderen Merkwürdigkeiten beobachtet.

Den 100ms Sleep werde ich in den nächsten Tagen mal in meine Produktivumgebung übernehmen und die Sache dann weiter beobachten. Falls nur das FritzBox Binding betroffen ist, könnte man damit mit Sicherheit auch leben. Ich habe aber eher die Befürchtung, dass der Bug hier nur aufgefallen, aber auch an anderen Stellen relevant ist...

[Jockel]

Nachdem der Workarround bei mir jetzt seit Mitte Februar ohne jedes Problem läuft wollte ich zu dem Thema noch mal ein Feedback geben. Nachteilige Effekte habe ich nicht bemerkt und ankommende Anrufe wurden bei mir seit dem Einbau des Wartens zuverlässig erkannt.

Natürlich ist das kein umfassender systematischer Test und ich bekomme auch keine 100 Anrufe am Tag, aber der Unterschied zu vorher ist deutlich. Daher würde ich dafür plädieren, den Workarround mit ins nächste Release aufzunehmen, zumindest so lange bis die wirkliche Ursache des Problems gefunden wurde.

Einen diff hab ich noch mal angehängt (mit Endung .txt, da er sonst vom Forum nicht akzeptiert wird).

[kkreuzer]

Danke fürs Feedback, habe den vorgeschlagenen Fix aufgenommen:
https://code.google.com/p/openhab/so...b586de7f602f7d

Viele Grüße,
Kai