[AVM Plugin] CallMonitor: Keine Anruf-Meldungen mehr nach einigen Stunden

[jentz1986]

Hallo zusammen,
ich hatte seit der Umstellung auf NG das Problem, dass der CallMonitor nach einem Neustart wunderbar funktionierte und nach einigen Stunden den Dienst eingestellt hat. Ich hatte daraufhin die Fritzbox im Verdacht und habe diese per SmarthomeNG zum nächtlichen Neustart verdonnert. Leider hat das diese Probleme nicht gelöst. Daraufhin habe ich den Loglevel auf Debug geändert, und mich dann über 120GB große Logfiles gefreut. (Läuft im Docker auf dem NAS, Platz "kein" Problem).
Ich habe mir diese Logfiles mal angeschaut. Nach dem Neustart der Box werden vom CallMonitor nur noch Whitespaces empfangen, ein Verbindungsabbruch wird da nicht detektiert.
Hat so etwas noch jemand beobachtet?

Ich habe daraufhin das 1.5.4er Plugin überarbeitet, so dass der CallMonitor per restart der Box auch disconnected wird, und bei jedem Update-Zyklus ein neues Verbinden versucht wird. Das hat letzte Nacht hervorragend funktioniert. Wenn das jetzt eine Woche problemlos funktioniert, würde ich das zur Verfügung stellen.
Wird der Pull-Request nach develop oder nach master gestellt? Ich bin da noch ein wenig neu...

[psilo]

Nach einem Neustart der Box wird derzeit der Thread mit der Verbindung zum Callmonitor (im Plugin) nicht mehr neu aufgebaut. Wenn mir jemand per PR Code gibt, mit dem ich das wegbrechen der Verbindung "detecten" kann, baue ich einen Reconnect gerne ein.
(daher: ja, PR gegen DEVELOP - falls es auch ohne Neustart der Box Verbindungsabbrueche gibt - das impliziert Dein Post - sollte der Fix idealerweise das auch handeln.. Poste gerne mal hier Deinen Code, dann schau ichs an und teste selber damit!)

So lange die Box läuft sollte die Verbindung aber EIGENTLICH bestehen bleiben!

[jentz1986]

Alles klar, wenn ich mit Testen und fixen durch bin, dann PR gegen develop. Den Code hier posten, gerne, aber das wäre viel Code mit kaum Änderungen, weil ich nur an ein paar Stellen if-else eingebaut habe und in die Reconnect-Methode:

          if self._call_monitor:
                self._monitoring_service.disconnect()

in der connect vom Monitoring Service:

        if self._listen_active:
            self.logger.debug("MonitoringService: Connect called while listen active")
            return

Aber da stimmt was anderes bei mir noch nicht. Jetzt habe ich eher den Verdacht, dass der Thread stirbt, weil es keine Fehlerbehandlung in _trigger gibt. Vielleicht sind meine Items nicht ganz sauber. Ich bau mal nen try ... except-Block ein und schau mal.

Ich glaube das, weil mein Log nach "_trigger:259" keine Zeilen zum Zählen der Länge des Anrufs enthält.

Entsprechend, weil bei allen anderen die Items sauber sind, tauchen dort auch keine Fehler auf und ich schieß erstmal in die falsche Richtung :-)

2018-12-10 14:18:15 CET DEBUG    __init__          MonitoringService_avm_fritzbox Data Received from CallMonitor: 10.12.18 14:18:15;CALL;1;11;##meine##;##andere##;SIP0;
  --  (__init__.py:_listen:173)
2018-12-10 14:18:15 CET DEBUG    __init__          MonitoringService_avm_fritzbox 10.12.18 14:18:15;CALL;1;11;##meine##;##andere##;SIP0;
  --  (__init__.py:_parse_line:238)
2018-12-10 14:18:15 CET DEBUG    __init__          MonitoringService_avm_fritzbox Event: CALL, Call From: ##meine##, Call To: ##andere##, Time: 10.12.18 14:18:15, CallID: 1  --  (__init__.py:_trigger:259)
2018-12-10 14:21:47 CET DEBUG    __init__          plugins.avm_fritzbox.update Starting update loop for instance fritzbox  --  (__init__.py:_update_loop:610)
2018-12-10 14:21:47 CET DEBUG    __init__          plugins.avm_fritzbox.update Accessing DeviceInfo reponse cache for action GetInfo!  --  (__init__.py:_update_fritz_device_info:1557)
2018-12-10 14:21:47 CET DEBUG    __init__          plugins.avm_fritzbox.update Accessing DeviceInfo reponse cache for action GetInfo!  --  (__init__.py:_update_fritz_device_info:1557)
2018-12-10 14:21:47 CET DEBUG    __init__          plugins.avm_fritzbox.update Accessing DeviceInfo reponse cache for action GetInfo!  --  (__init__.py:_update_fritz_device_info:1557)
2018-12-10 14:21:47 CET DEBUG    __init__          plugins.avm_fritzbox.update MonitoringService: Connect called while listen active  --  (__init__.py:connect:73)
2018-12-10 14:26:47 CET DEBUG    __init__          plugins.avm_fritzbox.update Starting update loop for instance fritzbox  --  (__init__.py:_update_loop:610)
2018-12-10 14:26:47 CET DEBUG    __init__          plugins.avm_fritzbox.update Accessing DeviceInfo reponse cache for action GetInfo!  --  (__init__.py:_update_fritz_device_info:1557)
2018-12-10 14:26:47 CET DEBUG    __init__          plugins.avm_fritzbox.update Accessing DeviceInfo reponse cache for action GetInfo!  --  (__init__.py:_update_fritz_device_info:1557)
2018-12-10 14:26:47 CET DEBUG    __init__          plugins.avm_fritzbox.update Accessing DeviceInfo reponse cache for action GetInfo!  --  (__init__.py:_update_fritz_device_info:1557)
2018-12-10 14:26:47 CET DEBUG    __init__          plugins.avm_fritzbox.update MonitoringService: Connect called while listen active  --  (__init__.py:connect:73)
2018-12-10 14:31:47 CET DEBUG    __init__          plugins.avm_fritzbox.update Starting update loop for instance fritzbox  --  (__init__.py:_update_loop:610)
2018-12-10 14:31:48 CET DEBUG    __init__          plugins.avm_fritzbox.update Accessing DeviceInfo reponse cache for action GetInfo!  --  (__init__.py:_update_fritz_device_info:1557)
2018-12-10 14:31:48 CET DEBUG    __init__          plugins.avm_fritzbox.update Accessing DeviceInfo reponse cache for action GetInfo!  --  (__init__.py:_update_fritz_device_info:1557)
2018-12-10 14:31:48 CET DEBUG    __init__          plugins.avm_fritzbox.update Accessing DeviceInfo reponse cache for action GetInfo!  --  (__init__.py:_update_fritz_device_info:1557)
2018-12-10 14:31:48 CET DEBUG    __init__          plugins.avm_fritzbox.update MonitoringService: Connect called while listen active  --  (__init__.py:connect:73)
2018-12-10 14:36:48 CET DEBUG    __init__          plugins.avm_fritzbox.update Starting update loop for instance fritzbox  --  (__init__.py:_update_loop:610)

[psilo]

Den Code hier posten, gerne, aber das wäre viel Code mit kaum Änderungen, weil ich nur an ein paar Stellen if-else eingebaut habe und in die Reconnect-Methode:

Du musst ja nicht die ganzen Klassen posten sondern nur das Diff. mit Rahmencode, so dass ich weiss, wo Du es eingefügt hast.

[jentz1986]

Ich sag nur items:
Bei mir gibt es das item call_duration_outgoing einfach nicht. (Brauch ich ja nicht...)

2018-12-11 08:31:18 CET DEBUG    __init__          MonitoringService_avm_fritzbox Data Received from CallMonitor: 11.12.18 08:31:18;DISCONNECT;1;0;
  --  (__init__.py:_listen:173)
2018-12-11 08:31:18 CET DEBUG    __init__          MonitoringService_avm_fritzbox 11.12.18 08:31:18;DISCONNECT;1;0;   --  (__init__.py:_parse_line:238)
2018-12-11 08:31:18 CET DEBUG    __init__          MonitoringService_avm_fritzbox Event: DISCONNECT, Call From: , Call To: , Time: , CallID: 1  --  (__init__.py:_trigger:263)
2018-12-11 08:31:18 CET ERROR    __init__          MonitoringService_avm_fritzbox MonitoringService: Error during parsing: 'call_duration_outgoing'  --  (__init__.py:_parse_line:255)

Nichtsdestotrotz bevorzuge ich Code, der einem sagt, wo man falsch abgebogen ist, daher hab ich das Exceptionhandling an der Stelle einfach mal eingebaut und meine Änderungen mit denen des Dev-Branch zusammengeführt, damit ich die Dev-Version teste und nicht Master.

Jetzt krieg ich das Plugin auch durch ausgehende Telefonate auch nicht mehr aufs Kreuz gedreht. Ich teste weiter und poste dann die Changes und mach nen PR.

[jentz1986]

Soo: Hin und her telefoniert.

2018-12-11 09:39:49 CET ERROR    __init__          MonitoringService_avm_fritzbox MonitoringService: KeyError while handling Callmonitor response, propably missing item-definition for 'call_duration_outgoing'

Und danach funktionierts weiter.

Also Pull-Request erstellt, Nummer 191:
https://github.com/smarthomeNG/plugins/pull/191

für mich bleibt das jetzt erstmal so. Wenn mir was auffällt poste ich hier wieder, sonst ist das Thema wohl erstmal durch.

[psilo]

jentz1986 sorry ich verstehe es gerade noch nicht: hast du den KeyError auf basis deines Pullrequests derzeit noch? Fehlt das Item noch?!

[jentz1986]

Bisher ist der Thread einfach "gestorben". Daher habe ich die Fehlerbehandlung eingebaut, ohne die Items zu ändern, um eben den Fehler zu provozieren. Daher ist meine items.yaml immer noch falsch, aber ich bekomme die Fehlermeldung und die Funktionalität ist trotzdem gegeben und stabil.

Ich werde die items bei mir später noch nachziehen.

Ich könnte mir aber vorstellen, dass ich nicht der Einzige bin, der mal ein Item vergisst, oder einen Typo einbaut. Man merkt es ja nicht, weil es keine Fehlermeldung gibt. Ich finde es besser, wenn die Software mir sagt, wenn ich Mist baue; Das wollte ich liefern...