57_Calender: Problem mit Timeout bei Google Kalender

[kaihs]

Ich habe mehrere Google Kalender eingebunden.
Die haben auch alle mal funktioniert aber bei einem gibt es jetzt immer ein Timeout:

Code Auswählen Erweitern


2018.07.11 21:01:40 4: Calendar cal_Beruflich: Getting data from URL <hidden>
2018.07.11 21:02:12 1: Calendar cal_Beruflich: retrieval failed with error message read from https://calendar.google.com:443 timed out


Code Auswählen Erweitern


Internals:
   DEF        ical url https://calendar.google.com/calendar/ical/XXX%40group.calendar.google.com/private-XXX/basic.ics
   NAME       cal_Beruflich
   NOTIFYDEV  global
   NR         445
   NTFY_ORDER 50-cal_Beruflich
   STATE      triggered
   TYPE       Calendar
   READINGS:
     2018-07-11 20:09:55   calname         Beruflich
     2018-07-11 20:09:55   lastUpdate      2018-07-11 20:09:53
     2018-04-04 18:09:02   modeAlarm       
     2018-07-11 20:32:00   modeAlarmOrStart
     2018-04-04 18:09:02   modeAlarmed     
     2018-07-11 00:09:52   modeChanged     
     2018-07-10 20:09:52   modeEnd         
     2018-07-10 10:18:24   modeEnded       
     2018-07-11 20:32:00   modeStart       
     2018-07-11 00:09:52   modeStarted     
     2018-07-11 20:32:00   modeUpcoming   
     2018-07-11 20:09:55   nextUpdate      2018-07-11 21:09:53
     2018-07-11 21:41:46   nextWakeup      2018-07-11 22:41:14
     2018-07-11 21:41:46   state           triggered
Attributes:
   alias      Kalender beruflich
   cutoffOlderThan 300
   hideOlderThan 300
   room       Kalender
   update     async
   verbose    5
   webCmd     update:reload


Statt XXX in der URL steht da natürlich was anderes.

Wenn ich dieselbe URL per wget vom selben Rechner mit dem User fhem abrufe klappt das ohne Probleme.
Wenn dieselbe URL von einem Calender Device einer anderen fhem Installation auf einem anderen Rechner abrufe klappt es auch ohne Probleme.
Das Attribut SSLVerify ändert nichts.
Zurücksetzen der URL in der Google Kalender Einstellungen (d.h. es wird eine neue URL generiert) und verwenden der neuen URL ändert auch nichts.

Ich habe mal versucht mit 'tcpdump tcp port 443 and host calendar.google.com' die Kommunikation die zu einem Timeout führt aufzuzeichnen, siehe Anlage.
Ich  kann mir das dann mir Wireshark ansehen, werde aber leider aus den Ausgaben nicht schlau.

Auffallend sind am Ende

Code Auswählen Erweitern


125 1.976066 216.58.206.14 192.168.2.21 TLSv1.2 638 [TCP Spurious Retransmission] , Application Data
127 31.358768 192.168.2.21 216.58.206.14 TLSv1.2 97 Encrypted Alert
128 31.362211 192.168.2.21 216.58.206.14 TCP 66 46586 → 443 [RST, ACK] Seq=629 Ack=80318 Win=140160 Len=0 TSval=1199299441 TSecr=2082290858
129 31.369500 216.58.206.14 192.168.2.21 TCP 60 443 → 46586 [RST] Seq=80318 Win=0 Len=0

Hat jemand eine Idee was die Ursache sein könnte?

[betateilchen]

kannst Du bitte auch ein pcap File von einer funktionierenden Übertragung aufzeichnen?
Mich würde interessieren, was da der grundlegende Unterschied ist.

Im Moment sehe ich nur, dass der Zertifikatsaustausch offenbar funktioniert, aber danach passiert nix mehr.

Ich vermute, man muss eher in Richtung HttpUtils.pm weitersuchen als im Kalendermodul, auch wenn HttpUtils eher nicht die eigentliche Ursache sein wird.

[kaihs]

kannst Du bitte auch ein pcap File von einer funktionierenden Übertragung aufzeichnen?

Klar, siehe Anhang.

[kaihs]

Und hier noch ein Mitschnitt wenn ich Kalender der in fhem zu einem Timeout führt per wget abrufe.

[betateilchen]

In den pcap Dateien finde ich erstmal nichts Spannendes, das mit dem Kalender selbst zu tun hat.

Vielleicht solltest Du die Frage nochmal im Bereich für HttpUtils.pm stellen, kann sein, dass Rudi eine Idee hat, wie man das weiter analysieren kann.



Edit: sehe gerade, dass Du noch einen dritten Thread aufgemacht hast. Du hättest auch einfach diesen Thread verschieben können

[kaihs]

Ja, habe ich schon gemacht.

Danke für deine Analyse.

[kaihs]

Der Vollständigkeit halber hier noch die Aufzeichnung des Abrufs desselben Kalenders von der anderen fhem Installation der funktioniert.

Das stammt von einem x86 Rechner mit OpenSuSE Tumbleweed (perl 5, version 26, subversion 2 (v5.26.2) built for x86_64-linux-thread-multi).

Das Problem besteht auf einem Bananapi mit Debian Jessie (perl 5, version 20, subversion 2 (v5.20.2) built for arm-linux-gnueabihf-thread-multi-64int).

[rudolfkoenig]

Habe nicht wirklich eine Idee, aber:

- kannst du bitte pruefen, ob das Abholen des Kalenders mit FHEM von diesem Rechner klappt, wenn man nur eine Instanz definiert hat? Am liebsten waere mir das mit einer Mini-FHEM-Installation ala

Code Auswählen Erweitern

attr global logfile -
attr global modpath .

define cal Calendar ical url https://calendar.google.com/calendar/ical/XXX%40group.calendar.google.com/private-XXX/basic.ics
attr cal   cutoffOlderThan 300
attr cal   hideOlderThan 300
attr cal   update     async


- ich finde es komisch, das lastUpdate "2018-07-11 20:09:53" ist, nextUpdate "2018-07-11 21:09:53", und deine Logmessages vom "2018.07.11 21:01:40" stammen. Muss aber nichts heissen, da ich das Modul nicht kenne.

[kaihs]

- kannst du bitte pruefen, ob das Abholen des Kalenders mit FHEM von diesem Rechner klappt, wenn man nur eine Instanz definiert hat? Am liebsten waere mir das mit einer Mini-FHEM-Installation ala

Guter Ansatz. Dann funktioniert der Abruf 
Also verursacht irgendetwas in meiner Konfiguration das Problem. Da wird die Suche mühsam...

[rudolfkoenig]

Naechter Versuch: alle Calender Instanzen in der Mini-Version einbauen

[kaihs]

Auch mit drei Kalendern funktioniert es noch:

Code Auswählen Erweitern


2018.07.12 12:46:23 1: Including fhem_test.cfg
2018.07.12 12:46:23 5: Calendar cal1: FHEM initialization or rereadcfg triggered update, delay 2 seconds.
2018.07.12 12:46:23 5: Calendar cal2: FHEM initialization or rereadcfg triggered update, delay 2 seconds.
2018.07.12 12:46:23 5: Calendar cal3: FHEM initialization or rereadcfg triggered update, delay 2 seconds.
2018.07.12 12:46:23 0: Featurelevel: 5.8
2018.07.12 12:46:23 0: Server started with 4 defined entities (fhem.pl:16866/2018-06-14 perl:5.020002 os:linux user:kai pid:12070)
2018.07.12 12:46:25 4: Calendar cal1: Wakeup
2018.07.12 12:46:25 4: Calendar cal1: Updating...
2018.07.12 12:46:25 4: Calendar cal1: Getting data from URL <hidden>
2018.07.12 12:46:25 4: Calendar cal2: Wakeup
2018.07.12 12:46:25 4: Calendar cal2: Updating...
2018.07.12 12:46:25 4: Calendar cal2: Getting data from URL <hidden>
2018.07.12 12:46:25 4: Calendar cal3: Wakeup
2018.07.12 12:46:25 4: Calendar cal3: Updating...
2018.07.12 12:46:25 4: Calendar cal3: Getting data from URL <hidden>
2018.07.12 12:46:26 4: Calendar cal3: parsing data asynchronously (PID= 12071)
2018.07.12 12:46:26 5: Calendar cal3: control passed back to main loop.
2018.07.12 12:46:26 4: Calendar cal2: parsing data asynchronously (PID= 12072)
2018.07.12 12:46:26 5: Calendar cal2: control passed back to main loop.
2018.07.12 12:46:26 4: Calendar cal1: parsing data asynchronously (PID= 12073)
2018.07.12 12:46:26 5: Calendar cal1: control passed back to main loop.
2018.07.12 12:46:27 4: Calendar cal3: got result from asynchronous parsing.
2018.07.12 12:46:27 4: Calendar cal3: asynchronous parsing finished.
2018.07.12 12:46:27 4: Calendar cal3: merging data
2018.07.12 12:46:27 4: Calendar cal3: 86 records processed, 86 new, 0 known, 0 modified, 0 changed.
2018.07.12 12:46:27 4: Calendar cal3: creating calendar events
2018.07.12 12:46:27 4: Calendar cal3: Checking times...
2018.07.12 12:46:27 4: Calendar cal3: process ended.
2018.07.12 12:46:27 4: Calendar cal2: still waiting (read: no data).
2018.07.12 12:46:27 4: Calendar cal1: got result from asynchronous parsing.
2018.07.12 12:46:27 4: Calendar cal1: asynchronous parsing finished.
2018.07.12 12:46:27 4: Calendar cal1: merging data
2018.07.12 12:46:27 4: Calendar cal1: 10 records processed, 10 new, 0 known, 0 modified, 0 changed.
2018.07.12 12:46:27 4: Calendar cal1: creating calendar events
2018.07.12 12:46:29 4: Calendar cal1: Checking times...
2018.07.12 12:46:29 4: Calendar cal1: process ended.
2018.07.12 12:46:29 4: Calendar cal2: got result from asynchronous parsing.
2018.07.12 12:46:29 4: Calendar cal2: asynchronous parsing finished.
2018.07.12 12:46:29 4: Calendar cal2: merging data
2018.07.12 12:46:29 4: Calendar cal2: 110 records processed, 110 new, 0 known, 0 modified, 0 changed.
2018.07.12 12:46:29 4: Calendar cal2: creating calendar events
2018.07.12 12:46:29 4: Calendar cal2: Checking times...
2018.07.12 12:46:29 4: Calendar cal2: process ended.
[code]

Ich habe ja die Befürchtung, dass irgendwas völlig unerwartetes Einfluss auf den Kalenderabruf hat und ich mit binärer Suche durch meine Konfiguration (Server started with 443 defined entities) muss.
Da werde ich mich aber erst nach meinem Urlaub drum kümmern.

[mumpitzstuff]

Code Auswählen Erweitern

HttpUtils_NonblockingGet({
      url => $url,
      hideurl => 1,
      noshutdown => 1,
      hash => $hash,
      timeout => 30,
      type => 'caldata',
      removeall => $removeall,
      sslargs => $SSLArgs,
      t => $t,
      callback => \&Calendar_ProcessUpdate,
});

Im Code ist an der Stelle ein Timeout von 30s hinterlegt (soweit ich das auf die Schnelle sehen kann). Kann es vielleicht sein, das du in deinem belasteten System diese Zeit für den Download sprengst? Spaßeshalber versuch doch mal das Modul an der Stelle zu editieren und was Größeres einzutragen (60 oder sowas) und zu gucken ob es dann geht. Falls ja, würdest du zumindest die Ursache kennen und kannst den Author daraufhin ansprechen.

[kaihs]

Im Code ist an der Stelle ein Timeout von 30s hinterlegt (soweit ich das auf die Schnelle sehen kann). Kann es vielleicht sein, das du in deinem belasteten System diese Zeit für den Download sprengst? Spaßeshalber versuch doch mal das Modul an der Stelle zu editieren und was Größeres einzutragen (60 oder sowas) und zu gucken ob es dann geht. Falls ja, würdest du zumindest die Ursache kennen und kannst den Author daraufhin ansprechen.

Mit einem Timeout von 120 Sekunden klappt der Abruf in der Tat:

Code Auswählen Erweitern


2018.07.17 17:11:16 4: Calendar cal_Beruflich: Getting data from URL <hidden>
2018.07.17 17:11:56 4: Calendar cal_Beruflich: parsing data asynchronously (PID= 7043)
2018.07.17 17:11:56 5: Calendar cal_Beruflich: control passed back to main loop.
2018.07.17 17:12:00 4: Calendar cal_Beruflich: got result from asynchronous parsing.
2018.07.17 17:12:00 4: Calendar cal_Beruflich: asynchronous parsing finished.
2018.07.17 17:12:00 4: Calendar cal_Beruflich: merging data
2018.07.17 17:12:00 4: Calendar cal_Beruflich: 110 records processed, 110 new, 0 known, 0 modified, 0 changed.
2018.07.17 17:12:00 4: Calendar cal_Beruflich: creating calendar events
2018.07.17 17:12:00 4: Calendar cal_Beruflich: Checking times...
2018.07.17 17:12:01 4: Calendar cal_Beruflich: process ended.


Der Abruf dauert da genau 30 Sekunden, das ist aber nicht immer der Fall, teilweise dauert es fast eine Minute.
Warum das solange dauert ist mir aber weiterhin unklar, ein Abruf derselben URL per wget dauert weniger als 1 Sekunde.

[betateilchen]

Hast Du mal versucht, Deine Anzahl von Kalendern zeitlich zu entzerren?

Gab es nicht irgendwann dafür sogar eine alignTime in Calendar (es stand zumindest schon auf der ToDo Liste von Boris)

[kaihs]

Zu dem Zeitpunkt wo von dem letzten Log des Abrufs wurde nur dieser eine Kalender abgerufen. Das war auch bei den vorherigen Tests so, ich habe immer explizit ein set cal_Beruflich reload gemacht.

Jetzt geht der Abruf auf einmal wieder schnell (3 Sekunden):

Code Auswählen Erweitern


2018.07.17 18:36:07 4: Calendar cal_Beruflich: Getting data from URL <hidden>
2018.07.17 18:36:08 4: Calendar cal_Beruflich: parsing data asynchronously (PID= 12939)
2018.07.17 18:36:08 5: Calendar cal_Beruflich: control passed back to main loop.
2018.07.17 18:36:09 4: Calendar cal_Beruflich: still waiting (read: no data).
2018.07.17 18:36:10 4: Calendar cal_Beruflich: got result from asynchronous parsing.
2018.07.17 18:36:10 4: Calendar cal_Beruflich: asynchronous parsing finished.
2018.07.17 18:36:10 4: Calendar cal_Beruflich: merging data
2018.07.17 18:36:11 4: Calendar cal_Beruflich: 109 records processed, 109 new, 0 known, 0 modified, 0 changed.
2018.07.17 18:36:11 4: Calendar cal_Beruflich: creating calendar events
2018.07.17 18:36:11 4: Calendar cal_Beruflich: Checking times...
2018.07.17 18:36:11 4: Calendar cal_Beruflich: process ended.


Ich habe einen Eintrag in dem Kalender gelöscht, aber ob das wirklich die Ursache war?