57_Calendar.pm: Exchange Kalender verursacht 'HTTP Response Code 503'

[JudgeDredd]

Hallo Zusammen,

ich habe mehrere MS-Exchange Kalender in FHEM definiert.
Erstmal funktionieren die auch unauffällig. Wenn ich allerdings FHEM stoppe und (unverändert) wieder starte, erhalte ich
bei jedem Kalender Update-Zyklus im Log die Fehlermeldung:

Code Auswählen Erweitern

Calendar cal_MSE00A: retrieval failed with HTTP response code 503

Wenn ich nun beim Kalender in die DEF gehe und nur auf modify klicke ohne etwas zu ändern, rennt der Kalenderupdate wieder ohne fehler.
Aber eben wieder nur bis zum nächsten STOP/START von FHEM.

Natürlich Kann ich jederzeit mit einem wget die iCal Datei runterladen ohne Fehler.
Da scheint der Request vom Modul wohl irgendetwas anderes zu machen.

Evtl. Jemand eine Idee und kann mir helfen/erklären warum das Modul ein "503 Service Unavailable" liefert ?

Gruß,
JudgeDredd

[Dr. Boris Neubert]

Hi,

kannst Du bitte mal die Verbosity auf 5 hochdrehen und das Log nach

Code Auswählen Erweitern

set cal_MSE00A update

posten (vertrauliche Daten entfernen), wenn die Fehlersituation auftritt?

Viele Grüße
Boris

[JudgeDredd]

Hallo Boris,

vielen Dank daß Du mal ein Auge drauf werfen möchtest.
Das Debug hatte ich mir die Tage auch schonmal angesehen, aber erhellt hat es mich nicht.

Debug:

Code Auswählen Erweitern

HTTP/1.1 503 Service Unavailable
Cache-Control: no-cache, no-store
Pragma: no-cache
Content-Type: text/html; charset=utf-8
Expires: -1
Server: Microsoft-IIS/8.0
request-id: 2343e322-6700-45fe-bcf6-4ad99955029c
Set-Cookie: ClientId=LOGFRCVH0PFQSCGSEARW; expires=Mon, 26-Apr-2021 07:00:42 GMT; path=/; HttpOnly
X-CalculatedBETarget: exdag04-1.exchange.int
X-Content-Type-Options: nosniff
X-OWA-Error: Microsoft.Exchange.Data.Directory.SystemConfiguration.OverBudgetException
X-DiagInfo: EXDAG04-1
X-BEServer: EXDAG04-1
X-UA-Compatible: IE=EmulateIE7
X-AspNet-Version: 4.0.30319
Set-Cookie: X-BackEndCookie=; expires=Thu, 26-Apr-1990 07:00:42 GMT; path=/owa/calendar; secure; HttpOnly
Set-Cookie: OutlookSession=d277419c5dd1476d4daa39b9b4336407; path=/; HttpOnly
X-Powered-By: ASP.NET
X-FEServer: EXFE07
Date: Sun, 26 Apr 2020 07:00:42 GMT
Connection: close
Content-Length: 1465

Danach kommt logischerweise noch ein:

Code Auswählen Erweitern

Calendar cal_MSE00A: retrieved no or empty data

Gruß,
JudgeDredd

[Dr. Boris Neubert]

Hallo,

ich meinte, Du solltest alle Einträge des Kalenders aus dem FHEM-Log zeigen, nicht nur den Reply des Webservers.

Viele Grüße
Boris

[Otto123]

Hi,

ich denke ja der Exchange Server verweigert in dem Moment die Anmeldung bzw. es dauert zu lange bis er den Kalender zur Verfügung stellt. Ein regelmäßiges Update (Zeitraum?) verläuft immer ohne Fehler?

Die HTTP Antwort sagt (mir) ja nicht das der Client ein Problem hat, sondern das der HTTP Server Probleme hat die angeforderten Daten bereit zustellen. Wobei es sein kann, dass er Probleme mit der Anmeldung des Clients haben könnte.

Zur Fehlersuche könnte es auch helfen, das Log vom Microsoft IIS zu analysieren.

Gruß Otto

[JudgeDredd]

ich meinte, Du solltest alle Einträge des Kalenders aus dem FHEM-Log zeigen, nicht nur den Reply des Webservers.

Kein Problem, aber so viel mehr ist es leider auch nicht:

Code Auswählen Erweitern

2020.04.28 11:45:07 4: Calendar cal_MSE00A: Wakeup
2020.04.28 11:45:07 4: Calendar cal_MSE00A: Updating...
2020.04.28 11:45:07 4: Calendar cal_MSE00A: Getting data from URL <hidden>
2020.04.28 11:45:07 1: Calendar cal_MSE00A: retrieval failed with HTTP response code 503
2020.04.28 11:45:07 5: Calendar cal_MSE00A: HTTP response header:
HTTP/1.1 503 Service Unavailable
Cache-Control: no-cache, no-store
Pragma: no-cache
Content-Type: text/html; charset=utf-8
Expires: -1
Server: Microsoft-IIS/8.0
request-id: 2343e322-6700-45fe-bcf6-4ad99955029c
Set-Cookie: ClientId=LOGFRCVH0PFQSCGSEARW; expires=Wed, 28-Apr-2021 09:45:07 GMT; path=/; HttpOnly
X-CalculatedBETarget: exdag04-1.exchange.int
X-Content-Type-Options: nosniff
X-OWA-Error: Microsoft.Exchange.Data.Directory.SystemConfiguration.OverBudgetException
X-DiagInfo: EXDAG04-1
X-BEServer: EXDAG04-1
X-UA-Compatible: IE=EmulateIE7
X-AspNet-Version: 4.0.30319
Set-Cookie: X-BackEndCookie=; expires=Sat, 28-Apr-1990 09:45:07 GMT; path=/owa/calendar; secure; HttpOnly
Set-Cookie: OutlookSession=d277419c5dd1476d4daa39b9b4336407; path=/; HttpOnly
X-Powered-By: ASP.NET
X-FEServer: EXFE07
Date: Tue, 28 Apr 2020 09:45:07 GMT
Connection: close
Content-Length: 1465
2020.04.28 11:45:07 1: Calendar cal_MSE00A: retrieved no or empty data
2020.04.28 11:45:07 4: Calendar cal_MSE00A: Checking times...


Zur Fehlersuche könnte es auch helfen, das Log vom Microsoft IIS zu analysieren.

Ja, das wäre mir auch am liebsten, aber es ist ein Hosted-Exchange. Daher wird das mit den Logs nicht so einfach.

Ein regelmäßiges Update (Zeitraum?) verläuft immer ohne Fehler?

So ist der Ablauf:

• Alle Kalender  Updates laufen komplett ohne Fehler.
• Dann stoppt nachts ein maintenance Script den FHEM-Service, erledigt Dinge wie Backup, Update, etc.
• Dann wird der FHEM-Service wieder gestartet.
• Danach liefert das Kalender Update den Fehler 503
• Morgens geht dann der tolle Admin (ich  ) hin und klickt bei jedem Kalender einmal auf die DEF und auf MODIFY
• Jetzt läuft der Update Prozess wieder ohne Fehler bis zum nächsten maintenance

Zur Info:
Auch wenn ich manuell den FHEM-Service restarte, erhalte ich danach den 503.

[Otto123]

Muss es modify sein? Oder geht auch ein

Code Auswählen Erweitern

set cal_MSE00A update

[JudgeDredd]

Muss es modify sein? Oder geht auch ein

Code Auswählen Erweitern

set cal_MSE00A update

Mmmh, bei einem Adhoc untertage Test scheint es auch nach einem manuellen Update zu funktionieren.
Das würde ich aber morgen früh lieber nochmal verifizieren

[herrmannj]

mgl nicht relevant, trotzdem: ich habe vor kurzem 503 in einem anderen modul gesehen. Da war die Ursache im http-header accept und Content-Type (beim request). Vmtl war der server einfach blöd. Ohne ging es dann.

[Otto123]

Wenn es geht, dann muss es ja irgendein Zeitproblem beim Start sein - ohne eine wirklich eine Idee zu haben wo genau.

Ein würgaround wäre dann zumindest

Code Auswählen Erweitern

define FHEMinit notify global:INITIALIZED sleep 60;; set cal_MSE00A update

Ich will nicht sagen, dass der Server blöd ist, aber OWA ist zumindest speziell

[Dr. Boris Neubert]

Mmmh, bei einem Adhoc untertage Test scheint es auch nach einem manuellen Update zu funktionieren.
Das würde ich aber morgen früh lieber nochmal verifizieren

Das beruhigt mich etwas. Ich wüsste nämlich nicht, wo das Device ein Gedächtnis haben sollte, das durch Neuanlage zerstört wird.

Ich warte Deine Rückmeldung ab.

Ggf. müssen wir an den Request-Header ran, wie Joerg schreibt, wobei der ja untertägig keine Probleme zu machen scheint. Du machst doch untertägige Updates, oder?

[JudgeDredd]

Du machst doch untertägige Updates, oder?

Ja klar alle 15 Min. (900 Sek.)

Wir (oder besser ich) schaue dann mal morgen ....

[Otto123]

Ok nochmal nachgedacht:

erhalte ich
bei jedem Kalender Update-Zyklus im Log die Fehlermeldung:

Bedeutet ja: früh abgelehnt und dann für immer raus? Da bin ich mal gespannt ob ein update nach dem Neustart wirklich hilft.

@Boris Was macht er denn beim modify? update reload oder was anderes?

[Dr. Boris Neubert]

@Boris Was macht er denn beim modify? update reload oder was anderes?

Modify schmeißt das Device weg und legt es neu an. Danach läuft ein reload mit Zeitverzögerung.

Das entspricht Deinem Vorschlag von heute Mittag. Der passiert aber sowieso 10 bis 30 Sekunden nach der Initialisierung oder Neuladen der Konfiguration.

Das Modul hat kein Gedächnis.

@JudgeDredd: wenn das mit dem update nicht hinhaut: kannst Du bitte mal das Calendar-Device in eine separate Instanz von FHEM vereinzeln und sehen, ob das Problem dann auch noch auftritt?

[JudgeDredd]

Hallo,

es gibt ein paar neue Erkenntnisse.
Zum einen bleibt es dabei, das ein

Code Auswählen Erweitern

set cal_MSE00A update
ausreicht, den 503 Response-Fehler bis zum nächsten FHEM-Neustart zu beheben.

Mir ist noch eingefallen, das ich noch nicht allzu lange 3 Exchange Kalender in FHEM integriert habe. Daher bin ich mal in den Logs rückwärts gegangen und zu dem Zeitpunkt als es noch 1 Kalender war, überlebte das Update auch den FHEM-Neustart ohne Fehler.
Also erst seitdem ich mehrere (3 aktuell) verwende, tritt das Problem auf.
Ich habe den Updateintervall auch schon auf unterschiedliche Längen eingestellt, allerdings ohne Erfolg.
Kann es sein, das das Modul beim Start alle Kalender sofort abfragt ? Sollte das das Problem sein, dann wäre es aber merkwürdig, das der nächste Aufruf (der ja unterschiedlich erfolgt) auch fehl schlägt.

Gruß,
JudgeDredd

[Dr. Boris Neubert]

Hallo,

ich dachte, zufällig zwischen 10 bis 30 Sekunden nach der Initialisierung oder Neuladen der Konfiguration macht der Kalender ein update. Ich sehe aber gerade, dass ich diese Funktion entfernt habe.

Bitte setze im Kalendermodul 57_Calendar.pm vor die Zeile 1851 ein # zum Auskommentieren der Fixierung auf 2 Sekunden. Die gesamte Subroutine sieht danach so aus:

Code Auswählen Erweitern

sub Calendar_Notify($$)
{
  my ($hash,$dev) = @_;
  my $name  = $hash->{NAME};
  my $type  = $hash->{TYPE};

  return if($dev->{NAME} ne "global");
  return if(!grep(m/^INITIALIZED|REREADCFG$/, @{$dev->{CHANGED}}));

  return if($attr{$name} && $attr{$name}{disable});

  # update calendar after initialization or change of configuration
  # wait 10 to 29 seconds to avoid congestion due to concurrent activities
  Calendar_DisarmTimer($hash);
  my $delay= 10+int(rand(20));

  # delay removed until further notice
  # $delay= 2;  <---------- HIER!

  Log3 $hash, 5, "Calendar $name: FHEM initialization or rereadcfg triggered update, delay $delay seconds.";
  InternalTimer(time()+$delay, "Calendar_Wakeup", $hash, 0) ;

  return undef;
}
Viele Grüße
Boris

[JudgeDredd]

Hallo Boris,

nach der Auskommentierung läuft es nun auch nach Neustart von FHEM mit allen Kalendern.
Super und vielen Dank, das Du es Dir mal angesehen hast.

Frage:
Checkst Du das ins SVN ein oder soll ich es auf meine ToDo nehmen und es nach einem ModulUpdate händisch machen ?

Gruß,
JudgeDredd

[Dr. Boris Neubert]

Hurra!

Ich habe es eingecheckt. Ab morgen kommt es per Update für alle.

Viele Grüße
Boris

[JudgeDredd]

Hallo Boris,

leider muss ich das Thema doch noch mal aufgreifen.

Ich nutze aktuell 5 Kalender des gleichen Exchange. Grundsätzlich funktioniert auch alles, es kommt aber alle paar Tage vor das mindestens zwei Kalender das gleiche Delay zugewiesen bekommen und wieder auf den 503er laufen.
Ein Vorschlag wäre (falls es Du es auch als sinnvoll erachtest und es nicht zu aufwändig ist), ein Default-Delay als optionalen Parameter im Define mitzugeben.
Dann könnten so komische Leute wie ich , die 5 oder mehr Kalender haben die Verzögerung manuell in gewissen Abständen setzen. Alternativ könnte man auch den Zufallsbereich vergrößern, aber dann sinkt ja nur die Wahrscheinlichkeit.

Gruß,
JudgeDredd

[Dr. Boris Neubert]

Hallo,

bitte teste mal die angehängte Datei. Neues Attribut delay.

Viele Grüße
Boris

[JudgeDredd]

Du bist aber von der ganz fixen Sorte
Datei werde ich testen, vermute aber, das es durch ein Attribut nicht verhindert werden kann.
Nach meinem Verständnis wird beim FHEM Neu-Start erst das DEFINE abgearbeitet und die Attribute greifen erst nach dem ersten Update.

Aber ich werde es auf jeden Fall testen und gebe Feedback ...

[Dr. Boris Neubert]

Die Aktualisierung des Kalenders wird (erst) getriggert, FHEM vollständig initialisiert ist. Dann sind die Attribute geladen. Die Aktualisierung findet nicht zum Zeitpunkt des DEFINE statt.

[JudgeDredd]

Hallo Boris,

der erste Testtag ist nun fehlerlos überstanden 
Ich habe meine Kalender im 5 Sekunden Abstand konfiguriert. Danach ca. 5 "shutdown restart" und alle ohne Fehler.
Auch die Nacht nach meinen maintanance Skripten verlief geräuschlos.
Ich würde mal sagen ... das sieht gut aus.

Dann nochmals vielen Dank für die prompte und kompetente Unterstützung.

Gruß,
JudgeDredd

[Dr. Boris Neubert]

eingespielt, wird morgen ab ca 8 Uhr per Update verteilt

Danke für Deinen Test!

[JudgeDredd]

Hallo Boris und auch andere Helferlein,

es gab bei diesem Modul ja mal den kleinen Bug mit dem Delay, der auch per 20.05.2020 behoben war.

Leider muss ich aber heute dieses Thema nochmal ansprechen.
Ich habe wieder seit einiger Zeit (ca. ende letzten Jahres) das Delay Problem erneut.

Mangels Zeit, habe ich es bis heute erstmal ignoriert.
Da aber durch die Behebung eines anderen Bugs Events fehlen, so dass meine Notify Logiken nicht mehr funktionieren, muss und ich nun doch mal in die Analyse gehen.

Wenn ich den Kalender auf verbose 5 stelle, sollte doch gem. SourceCode Zeile 1879

Code Auswählen Erweitern

Log3 $hash, 5, "Calendar $name: FHEM initialization or rereadcfg triggered update, delay $delay seconds.";
Die Info über die Anzahl der Verzögerungssekunden im Log auftauchen.

Diese fehlt aber. Was mich zu der Frage führt, wie weit die Modulfunktion

Code Auswählen Erweitern

sub Calendar_Notify($$)
beim INIT ausgeführt wird.

Nach meinen Bescheidenen Kenntnissen, kehrt er nach dieser Zeile aus der Sub wieder zurück:

Code Auswählen Erweitern

return if(!grep(m/^INITIALIZED|REREADCFG$/, @{$dev->{CHANGED}}));

Wäre es möglich dies mal durch einen anderen Nutzer des Moduls zu bestätigen und ggf. durch Boris zu korrigieren ?

Gruß,
JudgeDredd

[Dr. Boris Neubert]

Mangels Zeit, habe ich es bis heute erstmal ignoriert.
Da aber durch die Behebung eines anderen Bugs Events fehlen, so dass meine Notify Logiken nicht mehr funktionieren, muss und ich nun doch mal in die Analyse gehen.

Es fehlen nur Termine jenseits des Horizonts, also diejenigen, die zum Zeitpunkt des letzten Reloads oder Neustarts von FHEM weiter als min(400d; cutoffLaterThan) in der Zukunft liegen. Dem kann mit einem at-getriebenem Reload alle 30d abgeholfen werden.

Wenn ich den Kalender auf verbose 5 stelle, sollte doch gem. SourceCode Zeile 1879

Code Auswählen Erweitern

Log3 $hash, 5, "Calendar $name: FHEM initialization or rereadcfg triggered update, delay $delay seconds.";
Die Info über die Anzahl der Verzögerungssekunden im Log auftauchen.

Habe ich gerade versucht nachzuvollziehen, aber nur die Korrektheit bei mir bestätigt. Mit

Code Auswählen Erweitern

attr Calendar verbose 5 bekomme ich die Meldung im Log:

Code Auswählen Erweitern

2021.03.23 19:06:07 5: Calendar Calendar: FHEM initialization or rereadcfg triggered update, delay 14 seconds.


[JudgeDredd]

Hallo Boris,

Habe ich gerade versucht nachzuvollziehen, aber nur die Korrektheit bei mir bestätigt. Mit

Code Auswählen Erweitern

attr Calendar verbose 5 bekomme ich die Meldung im Log:

Code Auswählen Erweitern

2021.03.23 19:06:07 5: Calendar Calendar: FHEM initialization or rereadcfg triggered update, delay 14 seconds.


Ich fürchte, da muss ich wohl rurückrudern. 
Du hast Recht, den Logeintrag habe ich auch, er hat sich nur etwas zwischen anderen Zeilen als einzelner versteckt.

Das ändert allerdings nichts daran, das mehrere Kalender trotz unterschiedlicher delays versuchen zur gleichen Zeit zu aktualisieren.
Ich werde aber hier erstmal noch selbst nachforschen, bevor ich hier resourcen von anderen binde, die bestimmt besseres zu tun haben.

Das andere Kalenderphänomen das erst seit kurzem auftritt ist, das ich keine "modeUpcoming"-Events mehr bekomme.
Wenn ich bspw.:

13:45 -	neuen Termin im Exchange anlegen mit Beginn um 14 Uhr
13:50 -	FHEM Kalenderupdate
14:00 -	2021-03-24 14:00:00 Calendar cal_KALENDER changed: 040000008200E00074C5 ... CAED498F17D323FA7E21D0 start 2021-03-24 14:00:00 Calendar cal_KALENDER start: 040000008200E00074C5 ... CAED498F17D323FA7E21D0

Dann war es bisher so, das zwischen Kalenderupdate und Start des Termins ein "modeUpcoming"-Event erzeugt wurde.
Das scheint nun nicht mehr so zu sein.

Sagt Dir das spontan etwas, oder ist das auch eher ein Problem das nur auf meiner kleinen Insel existiert ?

[JudgeDredd]

UPDATE:

Das andere Kalenderphänomen das erst seit kurzem auftritt ist, das ich keine "modeUpcoming"-Events mehr bekomme.

Nach etwas forschen und erneutes lesen der Modul-Dokumentation, habe ich das:

Code Auswählen Erweitern

hasModeReadings
Set to 1 to use the obsolete mode readings.
entdeckt.

Das scheint recht neu zu sein und ist an mir wohl vorübergegangen.
Nach setzen auf "1", sind die mode...-Events wieder da.

Wie ist denn das "obsolete" zu verstehen ? Wird es evtl. in künftigen Modulupdates keine Möglichkeit mehr geben, mode...-Events zu erzeugen ?
Das wäre sehr schade, denn ich nutze diese Events zur Erzeugung von ATs zur Erinnerung 5 Minuten vor Beginn.

[Dr. Boris Neubert]

Hallo,

bereits vor zwei Jahren wurden die mode-Readings für tot erklärt. Jetzt habe ich die Ankündigung wahr gemacht, sie zu entfernen, und war so generös, das Attribut zu spendieren, sie wiederzuerwecken. 

Deine Aufgabe lässt sich leichter über ein Notify auf ein alarm-Event lösen und dieses kann, sofern nicht im Kalender, über ein onCreate-Plugin zugefügt werden. Dieser Standardanwendungsfall ist in der Commandref beschrieben.

Viele Grüße
Boris

[JudgeDredd]

Hallo Boris,

bereits vor zwei Jahren wurden die mode-Readings für tot erklärt. Jetzt habe ich die Ankündigung wahr gemacht, sie zu entfernen

Du bist aber auch echt Konsequent 

... und war so generös, das Attribut zu spendieren, sie wiederzuerwecken. 

Dank sei dem generösen Spender.

Deine Aufgabe lässt sich leichter über ein Notify auf ein alarm-Event lösen

Alarme im Kalender hasse  ich wie die Pest. Wenn alle Devices anfangen zu bimmeln 

und dieses kann, sofern nicht im Kalender, über ein onCreate-Plugin zugefügt werden.

Das habe ich gerade mal überflogen und schau mal, das ich das zeitnah umsetze und meine Notifys anpasse.
Ich hoffe Dein Drang zur endgültigen Entfernung ist noch etwas aushaltbar.

Gruß,
JudgeDredd