57_Calendar.pm - Abruf von AWM München blockiert FHEM

[weini]

Hallo zusammen!

Ich hatte mir vor ca. 1 Monat einen Abfallkalender aufgebaut. Grundlage ist ein iCAL Download von den AWM:

Code Auswählen Erweitern

https://www.awm-muenchen.de/index/abfuhrkalender.html?tx_awmabfuhrkalender_pi1[section]=ics&tx_awmabfuhrkalender_pi1[standplatzwahl]=true&tx_awmabfuhrkalender_pi1[singlestandplatz]=false&tx_awmabfuhrkalender_pi1[strasse]=Landwehrstr.&tx_awmabfuhrkalender_pi1[hausnummer]=10&tx_awmabfuhrkalender_pi1[stellplatz][restmuell]=70057572&tx_awmabfuhrkalender_pi1[stellplatz][papier]=70057572&tx_awmabfuhrkalender_pi1[stellplatz][bio]=70057572&tx_awmabfuhrkalender_pi1[leerungszyklus][R]=001;U&tx_awmabfuhrkalender_pi1[leerungszyklus][P]=001;U&tx_awmabfuhrkalender_pi1[leerungszyklus][B]=1/2;U&tx_awmabfuhrkalender_pi1[year]=2020
Die Adresse ist nicht meine, habe ich ausgetauscht 

Bis vor ein paar Tagen hat das auch super funktioniert. Seitdem hängt sich leider FHEM beim Update-Versuch komplett auf.

Hier das List vom Calendar:

Code Auswählen Erweitern

Internals:
   DEF        ical url https://www.awm-muenchen.de/index/abfuhrkalender.html?tx_awmabfuhrkalender_pi1[section]=ics&tx_awmabfuhrkalender_pi1[standplatzwahl]=true&tx_awmabfuhrkalender_pi1[singlestandplatz]=false&tx_awmabfuhrkalender_pi1[strasse]=Landwehrstr.&tx_awmabfuhrkalender_pi1[hausnummer]=10&tx_awmabfuhrkalender_pi1[stellplatz][restmuell]=70057572&tx_awmabfuhrkalender_pi1[stellplatz][papier]=70057572&tx_awmabfuhrkalender_pi1[stellplatz][bio]=70057572&tx_awmabfuhrkalender_pi1[leerungszyklus][R]=001;U&tx_awmabfuhrkalender_pi1[leerungszyklus][P]=001;U&tx_awmabfuhrkalender_pi1[leerungszyklus][B]=1/2;U&tx_awmabfuhrkalender_pi1[year]=%Y 604800
   FUUID      5ed21c0b-f33f-b8ff-f8cd-412a40d5550d03af
   NAME       calAbfall
   NOTIFYDEV  global
   NR         526
   NTFY_ORDER 50-calAbfall
   STATE      triggered
   TYPE       Calendar
   READINGS:
     2020-06-20 22:15:37   modeAlarm       
     2020-06-20 22:15:37   modeAlarmOrStart
     2020-06-20 22:15:37   modeAlarmed     
     2020-06-20 22:15:37   modeChanged     
     2020-06-20 22:15:37   modeEnd         
     2020-06-20 22:15:37   modeEnded       
     2020-06-20 22:15:37   modeStart       
     2020-06-20 22:15:37   modeStarted     
     2020-06-20 22:15:37   modeUpcoming   
     2020-06-21 10:18:11   nextWakeup      2020-06-28 10:18:11
     2020-06-21 10:18:11   state           triggered
Attributes:
   group      Abfall
   hideLaterThan 14d
   hideOlderThan 0d
   room       Unsorted
   verbose    5


Im Log sieht das dann so aus:

Code Auswählen Erweitern

2020.06.21 09:51:08.988 4: Calendar calAbfall: Updating...
2020.06.21 09:51:08.990 4: Calendar calAbfall: Getting data from URL <hidden>
2020.06.21 09:51:09.749 5: Calendar calAbfall: HTTP response code 200
2020.06.21 09:51:09.818 4: Calendar calAbfall: parsing data asynchronously (PID= 26868)
2020.06.21 09:51:09.821 5: Calendar calAbfall: control passed back to main loop.
2020.06.21 09:51:10.823 4: Calendar calAbfall: got result from asynchronous parsing.
2020.06.21 09:51:10.824 4: Calendar calAbfall: asynchronous parsing finished.
2020.06.21 09:51:10.841 4: Calendar calAbfall: merging data
2020.06.21 09:51:10.842 4: Calendar calAbfall: 3 records processed, 3 new, 0 known, 0 modified, 0 changed.
2020.06.21 09:51:10.842 4: Calendar calAbfall: creating calendar events
2020.06.21 09:51:10.843 1: PERL WARNING: Odd number of elements in hash assignment at ./FHEM/57_Calendar.pm line 1516.
2020.06.21 09:51:10.843 3: Calendar calAbfall: keyword MO in RRULE FREQ=WEEKLY;UNTIL=20201231;BYDAY=;WKST=MO is not supported

Angehängt ist noch das vollständige iCal.
Ich habe zwischenzeitlich nichts im FHEM aktualisiert. Daher vermute ich, dass der Provider im iCAL die Daten nun etwas anders bereitstellt. Als das Problem aufgetreten ist, habe ich dann einen kompletten FHEM Update gemacht. Das hat leider nichts gebracht. Mein FHEM läuft auf einem aktuellen Raspbian und wurde erst vor ca. 3 Monaten neu aufgesetzt, die Bibliotheken sollten also auch alle recht up to date sein (hier habe ich aber seitdem nichts aktualisiert).

Das iCAL sieht für mich auf den ersten Blick korrekt aus. Die Warning zu RRULE im Log ist komisch, weil dort "BYDAY=;" angegeben wird, in der iCAL aber "BYDAY=MO,MO;" steht.

Es wäre super, wenn sich das jemand ansehen könnte. Bitte gerne melden, wenn ich noch weiteren Input liefern kann.

Viele Grüße,
weini

[Dr. Boris Neubert]

Hallo,

mit der aktuellen Revision 21910 und dem angehängten iCalender bekomme ich die gezeigte Meldung nicht.

Viele Grüße
Boris

[weini]

Hallo Boris!

Guten Punkt, mit der ICS direkt habe ich noch gar nicht getestet. Ok, ich kann es nachvollziehen:

Code Auswählen Erweitern

defmod calAbfallTest Calendar ical file /opt/fhem/abfuhrkalender_landwehrstr_10_2020.ics
attr calAbfallTest group Abfall
attr calAbfallTest hideLaterThan 14d
attr calAbfallTest hideOlderThan 0d
attr calAbfallTest room Unsorted
attr calAbfallTest verbose 5


funktioniert, das Log dazu:

Code Auswählen Erweitern

2020.06.21 18:23:43.547 4: Calendar calAbfallTest: Updating...
2020.06.21 18:23:43.547 4: Calendar calAbfallTest: Getting data from file /opt/fhem/abfuhrkalender_landwehrstr_10_2020.ics
2020.06.21 18:23:43.548 5: Calendar calAbfallTest: file retrieval successful
2020.06.21 18:23:43.569 4: Calendar calAbfallTest: parsing data asynchronously (PID= 21824)
2020.06.21 18:23:43.572 5: Calendar calAbfallTest: control passed back to main loop.
2020.06.21 18:23:44.573 4: Calendar calAbfallTest: got result from asynchronous parsing.
2020.06.21 18:23:44.574 4: Calendar calAbfallTest: asynchronous parsing finished.
2020.06.21 18:23:44.658 4: Calendar calAbfallTest: merging data
2020.06.21 18:23:44.658 4: Calendar calAbfallTest: 8 records processed, 8 new, 0 known, 0 modified, 0 changed.
2020.06.21 18:23:44.660 4: Calendar calAbfallTest: creating calendar events
2020.06.21 18:23:44.731 4: Calendar calAbfallTest: Checking times...
2020.06.21 18:23:44.742 4: Calendar calAbfallTest: process ended.


Wenn ich allerdings direkt über die URL gehe:

Code Auswählen Erweitern

defmod calAbfallTest Calendar ical url https://www.awm-muenchen.de/index/abfuhrkalender.html?tx_awmabfuhrkalender_pi1[section]=ics&tx_awmabfuhrkalender_pi1[standplatzwahl]=true&tx_awmabfuhrkalender_pi1[singlestandplatz]=false&tx_awmabfuhrkalender_pi1[strasse]=Landwehrstr.&tx_awmabfuhrkalender_pi1[hausnummer]=10&tx_awmabfuhrkalender_pi1[stellplatz][restmuell]=70057572&tx_awmabfuhrkalender_pi1[stellplatz][papier]=70057572&tx_awmabfuhrkalender_pi1[stellplatz][bio]=70057572&tx_awmabfuhrkalender_pi1[leerungszyklus][R]=001;U&tx_awmabfuhrkalender_pi1[leerungszyklus][P]=001;U&tx_awmabfuhrkalender_pi1[leerungszyklus][B]=1/2;U&tx_awmabfuhrkalender_pi1[year]=%Y 604800
attr calAbfallTest group Abfall
attr calAbfallTest hideLaterThan 14d
attr calAbfallTest hideOlderThan 0d
attr calAbfallTest room Unsorted
attr calAbfallTest verbose 5


dann hängt FHEM beim Abruf des Kalenders:

Code Auswählen Erweitern

2020.06.21 18:16:33.418 1: Calendar calAbfallTest: retrieval failed with HTTP response code 400
2020.06.21 18:16:33.422 1: Calendar calAbfallTest: retrieved no or empty data
2020.06.21 18:17:39.690 4: Calendar calAbfallTest: Updating...
2020.06.21 18:17:39.694 4: Calendar calAbfallTest: Getting data from URL <hidden>
2020.06.21 18:17:40.290 5: Calendar calAbfallTest: HTTP response code 200
2020.06.21 18:17:40.345 4: Calendar calAbfallTest: parsing data asynchronously (PID= 21278)
2020.06.21 18:17:40.347 5: Calendar calAbfallTest: control passed back to main loop.
2020.06.21 18:17:41.347 4: Calendar calAbfallTest: got result from asynchronous parsing.
2020.06.21 18:17:41.348 4: Calendar calAbfallTest: asynchronous parsing finished.
2020.06.21 18:17:41.361 4: Calendar calAbfallTest: merging data
2020.06.21 18:17:41.361 4: Calendar calAbfallTest: 3 records processed, 3 new, 0 known, 0 modified, 0 changed.
2020.06.21 18:17:41.362 4: Calendar calAbfallTest: creating calendar events
2020.06.21 18:17:41.362 1: PERL WARNING: Odd number of elements in hash assignment at ./FHEM/57_Calendar.pm line 1516.
2020.06.21 18:17:41.363 3: Calendar calAbfallTest: keyword MO in RRULE FREQ=WEEKLY;UNTIL=20201231;BYDAY=;WKST=MO is not supported


Das ICS File habe ich exakt über die angegebene URL via Firefox gezogen.
Spannend finde ich, dass er einmal "8 Records" und einmal nur "3 Records" findet.

Viele Grüße,
Christian

[Dr. Boris Neubert]

Hallo,

ich denke, hier liegt das Problem:

Code Auswählen Erweitern

2020.06.21 18:16:33.418 1: Calendar calAbfallTest: retrieval failed with HTTP response code 400


Es gab kürzlich Änderungen an HttpUtils.pm. Das könnte die Ursache sein.

Wenn Du mal auf eine Version von FHEM von vor dem 25.05.2020 zurückgehst und es dann wieder geht, dann bin ich ziehmlich sicher, dass die Änderung an HttpUtils der Grund ist.

Viele Grüße
Boris

[weini]

Hallo Boris!

Bist du sicher?
Die Meldung "retrieval failed with HTTP response code 400" kommt beim Anlegen des Device.
Wenn ich dann "reload" ausführe, dann kommen die Logs ab

Code Auswählen Erweitern

2020.06.21 18:17:39.690 4: Calendar calAbfallTest: Updating...
und erst dann hängt FHEM.

Das würde auch nicht dazu passen, dass das bei mir mal wunderbar funktioniert hat und dann (mit dem identischen SW-Stand, keine Updates) jetzt nicht mehr. Den Thread zu HttpUtils  hatte ich gelesen. Da aber das Problem in HttpUtils angeblich gefixt ist und ich bei mir gestern alles upgedated habe, sollte das nicht mehr auftreten.

Ich probiere es jetzt aber trotzdem gleich nochmal aus, Rückmeldung folgt.

Viele Grüße,
weini

[weini]

Habs getestet mit der HttpUtils die du hier https://forum.fhem.de/index.php/topic,111718.msg1060852.html#msg1060852 angehängt hattest.
Es kommen die selben Log-Meldungen und FHEM hängt sich nach Ausführen von reload auch damit auf.

[Dr. Boris Neubert]

Hi,

was meinst Du mit aufhängen?

Viele Grüße
Boris

[weini]

Totales Blockieren!
Die geposteten Log-Einträge sind das Ende, danach passiert nichts mehr. Web & Telnet Interfaces sind tot.
Normal schlägt dann nach 180 Sekunden der systemd Watchdog zu. Ich hatte ihn aber auch schon mal deaktiviert. Auch nach 5-10 Minuten hat sich nichts getan.

VG,
weini

[amenomade]

Hast Du mal versucht, den Kalender über deine URL zu holen, und mit einem Editor drinn zu gucken?

Habs gerade gemacht:
Die VEVENTS sehen so aus:

Code Auswählen Erweitern

BEGIN:VEVENT
DTSTAMP:20200621T234728Z
UID:PuL3pjhuYtPdRnpoa93WMDSNq1AKYQJOkuSJN9eM@awm-muenchen.de
SUMMARY:Restmülltonne, Landwehrstr. 10

DTSTART;TZID=Europe/Berlin;VALUE=DATE:19700101
DTEND;TZID=Europe/Berlin;VALUE=DATE:19700101

LOCATION:Landwehrstr. 10, München
DESCRIPTION:Stellplatz: Landwehrstr. 10
STATUS:CONFIRMED

RRULE:FREQ=WEEKLY;UNTIL=%Y1231;BYDAY=MO,MO;WKST=MO

BEGIN:VALARM
TRIGGER:-PT15H
ACTION:DISPLAY

DESCRIPTION:Restmülltonne, Landwehrstr. 10
END:VALARM
END:VEVENT



Ich weiss nicht, wie das Modul gebaut ist, aber mit Anfang 1970 und wöchentliche Wiederholung bis Ende dieses Jahres (wenn er schon UNTIL=%Y1231 richtig interpretieren kann) könnte ich mir schon vorstellen, dass er viel zu tun hat... Das macht nur für Restmülltonne potentiel 2600 Termine zu kalkulieren. Genauso für Papier. Zum Glück ist Biotonne nur jede 2. Woche

[weini]

Das ist ja spannend!

Mit welcher URL genau hast du denn dieses ICS gezogen?
Die ICS, die ich erhalte, sehe alle so aus:

Code Auswählen Erweitern

BEGIN:VCALENDAR
VERSION:2.0
PRODID:-//Abfallwirtschaftsbetrieb München//Abfuhrkalender//DE
CALSCALE:GREGORIAN
BEGIN:VEVENT
DTSTAMP:20200621T083649Z
UID:XuQMUwV1fwfAfzIsM0EUHJBEeHfERP7OjXBduwfK@awm-muenchen.de
SUMMARY:Restmülltonne, Landwehrstr. 10
DTSTART;TZID=Europe/Berlin;VALUE=DATE:20200615
DTEND;TZID=Europe/Berlin;VALUE=DATE:20200616
LOCATION:Landwehrstr. 10, München
DESCRIPTION:Stellplatz: Landwehrstr. 10
STATUS:CONFIRMED
RRULE:FREQ=WEEKLY;UNTIL=20201231;BYDAY=MO,MO;WKST=MO
EXDATE;VALUE=DATE:20201221T000000
EXDATE;VALUE=DATE:20201228T000000
EXDATE;VALUE=DATE:20200406T000000
EXDATE;VALUE=DATE:20200413T000000
EXDATE;VALUE=DATE:20200504T000000
EXDATE;VALUE=DATE:20200601T000000

URL:
=ics&tx_awmabfuhrkalender_pi1[standplatzwahl]=true&tx_awmabfuhrkalender_pi1[singlestandplatz]=false&tx_awmabfuhrkalender_pi1[strasse]=Landwehrstr.&tx_awmabfuhrkalender_pi1[hausnummer]=10&tx_awmabfuhrkalender_pi1[stellplatz][restmuell]=70057572&tx_awmabfuhrkalender_pi1[stellplatz][papier]=70057572&tx_awmabfuhrkalender_pi1[stellplatz][bio]=70057572&tx_awmabfuhrkalender_pi1[leerungszyklus][R]=001;U&tx_awmabfuhrkalender_pi1[leerungszyklus][P]=001;U&tx_awmabfuhrkalender_pi1[leerungszyklus]=1/2;U&tx_awmabfuhrkalender_pi1[year]=2020]https://www.awm-muenchen.de/index/abfuhrkalender.html?tx_awmabfuhrkalender_pi1[section]=ics&tx_awmabfuhrkalender_pi1[standplatzwahl]=true&tx_awmabfuhrkalender_pi1[singlestandplatz]=false&tx_awmabfuhrkalender_pi1[strasse]=Landwehrstr.&tx_awmabfuhrkalender_pi1[hausnummer]=10&tx_awmabfuhrkalender_pi1[stellplatz][restmuell]=70057572&tx_awmabfuhrkalender_pi1[stellplatz][papier]=70057572&tx_awmabfuhrkalender_pi1[stellplatz][bio]=70057572&tx_awmabfuhrkalender_pi1[leerungszyklus][R]=001;U&tx_awmabfuhrkalender_pi1[leerungszyklus][P]=001;U&tx_awmabfuhrkalender_pi1[leerungszyklus]=1/2;U&tx_awmabfuhrkalender_pi1[year]=2020

Ich sehe gerade in der Vorschau, dass die Board-SW die Formatierung der URL durcheinanderbringt. Wenn man sie klickt, dann sollte es aber stimmen.

Ich habe nochmal einen Versuch via IE gemacht (normal nutze ich FF), nicht dass die Website bei mir irgendwelche Cookies gesetzt hat. Meine ICS Dateien haben aber nie ein 1970er Datum drin.

[Dr. Boris Neubert]

Hallo,

um amenomades Idee nachzuspüren bitte ich Dich, in Zeile 2803 von Calender.pm im Code folgendes einzubauen:

Code Auswählen Erweitern

main::Debug $ics;

Dann wird ins Log geschrieben, wie der heruntergeladene Kalender tatsächlich aussieht. Das ist die Grundlage für weitere Analysen.

Grüße
Boris

[amenomade]

Nur zur Info: ich habe einfach die URL aus der DEF genommen, ohne %Y durch 2020 zu ersetzen.

Mit Ersetzung sieht es so aus:

Code Auswählen Erweitern

BEGIN:VCALENDAR
VERSION:2.0
PRODID:-//Abfallwirtschaftsbetrieb München//Abfuhrkalender//DE
CALSCALE:GREGORIAN
BEGIN:VEVENT
DTSTAMP:20200622T090115Z
UID:igXuY9LXEDcBbSKd0PwJP2V7gNgl5lYoBWSA6EyK@awm-muenchen.de
SUMMARY:Restmülltonne, Landwehrstr. 10
DTSTART;TZID=Europe/Berlin;VALUE=DATE:20200622
DTEND;TZID=Europe/Berlin;VALUE=DATE:20200623
LOCATION:Landwehrstr. 10, München
DESCRIPTION:Stellplatz: Landwehrstr. 10
STATUS:CONFIRMED
RRULE:FREQ=WEEKLY;UNTIL=20201231;BYDAY=MO,MO;WKST=MO
EXDATE;VALUE=DATE:20201221T000000
EXDATE;VALUE=DATE:20201228T000000
EXDATE;VALUE=DATE:20200406T000000
EXDATE;VALUE=DATE:20200413T000000
EXDATE;VALUE=DATE:20200504T000000
EXDATE;VALUE=DATE:20200601T000000
BEGIN:VALARM
TRIGGER:-PT15H
ACTION:DISPLAY
DESCRIPTION:Restmülltonne, Landwehrstr. 10
END:VALARM
END:VEVENT
Das war nur eine Idee. Da müsste man aber doch ins Debug gehen, wie Boris gesagt hat. Wenn Calendar Probleme macht, gehe ich immer eher davon aus, dass die Daten des Kalenders die Ursache sind.

[weini]

@amenomade: Ok, das erklärt die Diskrepanz

@Boris: Gerne, hier das Log:

Code Auswählen Erweitern


2020.06.22 11:20:18.290 1: DEBUG>BEGIN:VCALENDAR
VERSION:2.0
PRODID:-//Abfallwirtschaftsbetrieb München//Abfuhrkalender//DE
CALSCALE:GREGORIAN
BEGIN:VEVENT
DTSTAMP:20200622T092018Z
UID:DyXRNF1Mfmh0vJZSwWhx15x0q8xDIzPm7MdUsfGI@awm-muenchen.de
SUMMARY:Restmülltonne, landwehrstr. 10
DTSTART;TZID=Europe/Berlin;VALUE=DATE:20200621
DTEND;TZID=Europe/Berlin;VALUE=DATE:20200622
LOCATION:Landwehrstr. 10, München
DESCRIPTION:Stellplatz: Landwehrstr. 10
STATUS:CONFIRMED
RRULE:FREQ=WEEKLY;UNTIL=20201231;BYDAY=;WKST=MO
BEGIN:VALARM
TRIGGER:-PT15H
ACTION:DISPLAY
DESCRIPTION:Restmülltonne, landwehrstr. 10
END:VALARM
END:VEVENT
BEGIN:VEVENT
DTSTAMP:20200622T092018Z
UID:CXJ7HJZdFhKGnhHNpeq8OgvW3JQwYxfAvYIdHIrn@awm-muenchen.de
SUMMARY:Papiertonne, landwehrstr. 10
DTSTART;TZID=Europe/Berlin;VALUE=DATE:20200621
DTEND;TZID=Europe/Berlin;VALUE=DATE:20200622
LOCATION:Landwehrstr. 10, München
DESCRIPTION:Stellplatz: Landwehrstr. 10
STATUS:CONFIRMED
RRULE:FREQ=WEEKLY;UNTIL=20201231;BYDAY=;WKST=MO
BEGIN:VALARM
TRIGGER:-PT15H
ACTION:DISPLAY
DESCRIPTION:Papiertonne, landwehrstr. 10
END:VALARM
END:VEVENT
BEGIN:VEVENT
DTSTAMP:20200622T092018Z
UID:Zc4ntLaT0B2OSyLVhBsf9HQFFzSnhkLhwPE0BPUB@awm-muenchen.de
SUMMARY:Biotonne, landwehrstr. 10
DTSTART;TZID=Europe/Berlin;VALUE=DATE:20200621
DTEND;TZID=Europe/Berlin;VALUE=DATE:20200622
LOCATION:Landwehrstr. 10, München
DESCRIPTION:Stellplatz: Landwehrstr. 10
STATUS:CONFIRMED
RRULE:FREQ=WEEKLY;UNTIL=20201231;BYDAY=;WKST=MO
BEGIN:VALARM
TRIGGER:-PT15H
ACTION:DISPLAY
DESCRIPTION:Biotonne, landwehrstr. 10
END:VALARM
END:VEVENT
END:VCALENDAR
2020.06.22 11:20:19.390 1: PERL WARNING: Odd number of elements in hash assignment at ./FHEM/57_Calendar.pm line 1516.
2020.06.22 11:20:19.391 3: Calendar calAbfallTest: keyword MO in RRULE FREQ=WEEKLY;UNTIL=20201231;BYDAY=;WKST=MO is not supported


Die RRULE ist tatsächlich durch die Mangel gedreht. Die sieht im heruntergeladenen ICS File auch anders aus.

[Dr. Boris Neubert]

Die RRULE ist tatsächlich durch die Mangel gedreht. Die sieht im heruntergeladenen ICS File auch anders aus.

Das ist sehr komisch. Wenn ich die URL aus der Definition des Kalenders (mit 2020 statt %Y) im Browser eingebe, bekomme ich die korrekte Datei. FHEM lädt aber etwas anderes herunter.

Wie kommt das? Ich bin ratlos. Müsste man einen Test für HttpUtils schreiben.

[weini]

Da bin ich ja froh, dass es mir nicht alleine so geht.

Jetzt kann ich aber nochmal etwas Licht ins Dunkel bringen: Wenn ich von meinem Raspi aus die URL mit "wget" ziehe, dann bekomme ich den selben Mist - also auch die fehlerhafte RULE Zeile.

Das sieht mir eher nach einem Server-seitigem Issue aus...