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:
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
Hi,
kannst Du bitte mal die Verbosity auf 5 hochdrehen und das Log nach
set cal_MSE00A update
posten (vertrauliche Daten entfernen), wenn die Fehlersituation auftritt?
Viele Grüße
Boris
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:
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:
Calendar cal_MSE00A: retrieved no or empty data
Gruß,
JudgeDredd
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
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
Zitat von: Dr. Boris Neubertich 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:
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...
Zitat von: Otto123Zur 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.
Zitat von: Otto123Ein 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 ;D) 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.
Muss es modify sein? Oder geht auch ein
set cal_MSE00A update
Zitat von: Otto123Muss es modify sein? Oder geht auch ein
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
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.
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
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 ;)
Zitat von: JudgeDredd am 28 April 2020, 14:35:20
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?
Zitat von: Dr. Boris NeubertDu machst doch untertägige Updates, oder?
Ja klar alle 15 Min. (900 Sek.)
Wir (oder besser ich) schaue dann mal morgen ....
Ok nochmal nachgedacht:
Zitaterhalte 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?
Zitat von: Otto123 am 28 April 2020, 15:15:22
@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?
Hallo,
es gibt ein paar neue Erkenntnisse.
Zum einen bleibt es dabei, das ein
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
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:
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
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
Hurra!
Ich habe es eingecheckt. Ab morgen kommt es per Update für alle.
Viele Grüße
Boris
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
Hallo,
bitte teste mal die angehängte Datei. Neues Attribut delay.
Viele Grüße
Boris
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 ...
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.
Hallo Boris,
der erste Testtag ist nun fehlerlos überstanden :D
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
eingespielt, wird morgen ab ca 8 Uhr per Update verteilt
Danke für Deinen Test!
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 (https://forum.fhem.de/index.php/topic,119638.msg1140739.html#msg1140739) 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
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
sub Calendar_Notify($$)
beim INIT ausgeführt wird.
Nach meinen Bescheidenen Kenntnissen, kehrt er nach dieser Zeile aus der Sub wieder zurück:
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
Zitat von: JudgeDredd am 23 März 2021, 09:21:02
Mangels Zeit, habe ich es bis heute erstmal ignoriert.
Da aber durch die Behebung eines anderen Bugs (https://forum.fhem.de/index.php/topic,119638.msg1140739.html#msg1140739) 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.
Zitat
Wenn ich den Kalender auf verbose 5 stelle, sollte doch gem. SourceCode Zeile 1879
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
attr Calendar verbose 5 bekomme ich die Meldung im Log:
2021.03.23 19:06:07 5: Calendar Calendar: FHEM initialization or rereadcfg triggered update, delay 14 seconds.
Hallo Boris,
Zitat von: Dr. Boris Neubert am 23 März 2021, 19:08:19Habe ich gerade versucht nachzuvollziehen, aber nur die Korrektheit bei mir bestätigt. Mit attr Calendar verbose 5 bekomme ich die Meldung im Log:
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 ?
UPDATE:Zitat von: JudgeDredd am 24 März 2021, 14:24:56
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:
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.
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. :D
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
Hallo Boris,
Zitat von: Dr. Boris Neubert am 25 März 2021, 18:30:29
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 ;D
Zitat von: Dr. Boris Neubert am 25 März 2021, 18:30:29
... und war so generös, das Attribut zu spendieren, sie wiederzuerwecken. :D
Dank sei dem generösen Spender.
Zitat von: Dr. Boris Neubert am 25 März 2021, 18:30:29
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 >:(
Zitat von: Dr. Boris Neubert am 25 März 2021, 18:30:29
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