[gelöst?][98_JsonMod.pm] Main process exited, code=killed, status=11

[yersinia]

Hallo zusammen,

in unregelmäßigen Abständen und für mich nicht reproduzierbar stürzt FHEM ab.

System ist (siehe auch Signatur) ein RasPi 4 mit RaspberryPI-OS (exRaspbian) 10; kernel 5.10.11-v7l; System ist aktuell; perl 5.28.1; FHEM Update war zum Zeitpunkt des Absturzes auf Revision 23861 von Montag gefolgt von einem shutdown restart. Die SD-Karte ist < 1 Jahr im Einsatz.

Im Systemlog (journalctl) steht dann

Code Auswählen Erweitern

Mär 04 18:09:00 raspi4 systemd[1]: fhem.service: Main process exited, code=killed, status=11/SEGV
Mär 04 18:09:00 raspi4 systemd[1]: fhem.service: Failed with result 'signal'.
Mär 04 18:09:00 raspi4 systemd[1]: fhem.service: Service RestartSec=100ms expired, scheduling restart.
Mär 04 18:09:00 raspi4 systemd[1]: fhem.service: Scheduled restart job, restart counter is at 5.
Mär 04 18:09:00 raspi4 systemd[1]: Stopped FHEM Home Automation.
Mär 04 18:09:00 raspi4 systemd[1]: Starting FHEM Home Automation...
Mär 04 18:09:00 raspi4 systemd[1]: Started FHEM Home Automation.
Im FHEM-log steht nichts außer dass der Server um 18:09:00 gestartet wird - davor gibt es keine Hinweise (verbose global ist 3).

Es gibt ein JsonMod Device welches genau um 18:09:00 triggern würde - vielleicht (!) hängt dies damit zusammen? Ist aber nur eine Vermutung weil es zufällig die gleiche Uhrzeit ist. List des Devices:

Code Auswählen Erweitern

Internals:
   API_LAST_RES 1614931740.21099
   API__LAST_MSG 200
   DEF        https://services7.arcgis.com/mOBPykOjAyBO2ZKk/arcgis/rest/services/Coronaf%C3%A4lle_in_den_Bundesl%C3%A4ndern/FeatureServer/0/query?where=1%3D1&outFields=LAN_ew_GEN,Fallzahl,Aktualisierung,faelle_100000_EW,cases7_bl_per_100k,Death&returnGeometry=false&outSR=4326&f=json
   FUUID      5e7ca251-f33f-3151-a7c5-1917ebe9dec5a5d4
   NAME       coronaSpreadDE
   NEXT       2021-03-05 12:09:00
   NR         321
   SOURCE     https://services7.arcgis.com/mOBPykOjAyBO2ZKk/arcgis/rest/services/Coronaf%C3%A4lle_in_den_Bundesl%C3%A4ndern/FeatureServer/0/query?where=1%3D1&outFields=LAN_ew_GEN,Fallzahl,Aktualisierung,faelle_100000_EW,cases7_bl_per_100k,Death&returnGeometry=false&outSR=4326&f=json (200)
   STATE      <div style="text-align: left;">last <a href="https://corona.rki.de" title="RKI CoViD19" rel="noopener noreferrer" target="_blank">RKI CoViD-19</a> check => 05.03. 09:09<br />Hessen:&nbsp;<font style="font-weight:bold;color:red;">63.9</font>&nbsp;&amp;&nbsp;<font style="color:orange;font-weight:bold;">540421 F&auml;lle</font>&nbsp;&amp;&nbsp;<font style="color:red;font-weight:bold;">13310 Tote</font>&nbsp;(05.03. 00:00)<br />Niedersachsen:&nbsp;<font style="font-weight:bold;color:red;">86.6</font>&nbsp;&amp;&nbsp;<font style="color:orange;font-weight:bold;">61930 F&auml;lle</font>&nbsp;&amp;&nbsp;<font style="color:red;font-weight:bold;">2479 Tote</font>&nbsp;(05.03. 00:00)</div>
   SVN        22987 2020-10-18 13:26:05 UTC
   TYPE       JsonMod
   .attreour:
     .computedReadings
   .attrminint:
   .userReadings:
     HASH(0x503a6a0)
     HASH(0x50ff200)
   CONFIG:
     IN_REQUEST 0
     SOURCE     https://services7.arcgis.com/mOBPykOjAyBO2ZKk/arcgis/rest/services/Coronaf%C3%A4lle_in_den_Bundesl%C3%A4ndern/FeatureServer/0/query?where=1%3D1&outFields=LAN_ew_GEN,Fallzahl,Aktualisierung,faelle_100000_EW,cases7_bl_per_100k,Death&returnGeometry=false&outSR=4326&f=json
     SECRET:
   READINGS:
     2021-03-05 09:09:00   .computedReadings 0_cases,0_lastUpdate,0_cases7_bl_per_100k,1_name,1_lastUpdate,1_cases,1_cases7_bl_per_100k,0_name,0_deaths,1_deaths
     2021-03-05 09:09:00   0_cases         540421
     2021-03-05 09:09:00   0_cases7_bl_per_100k 63.8650407213462
     2021-03-05 09:09:00   0_deaths        13310
     2021-03-05 09:09:00   0_lastUpdate    1614898800000
     2021-03-05 09:09:00   0_lastUpdatedh  05.03. 00:00
     2021-03-05 09:09:00   0_name          Hessen
     2021-03-05 09:09:00   1_cases         61930
     2021-03-05 09:09:00   1_cases7_bl_per_100k 86.5689622021686
     2021-03-05 09:09:00   1_deaths        2479
     2021-03-05 09:09:00   1_lastUpdate    1614898800000
     2021-03-05 09:09:00   1_lastUpdatedh  05.03. 00:00
     2021-03-05 09:09:00   1_name          Niedersachsen
Attributes:
   DbLogExclude .*
   event-on-update-reading .computedReadings
   interval   9 */3 * * *
   readingList multi(jsonPath("\$.features[?(\@.attributes.LAN_ew_GEN in ['Hessen', 'Niedersachsen'])]"), concat(count(),'_name'), property('attributes.LAN_ew_GEN'));
multi(jsonPath("\$.features[?(\@.attributes.LAN_ew_GEN in ['Hessen', 'Niedersachsen'])]"), concat(count(),'_cases'), property('attributes.Fallzahl'));
multi(jsonPath("\$.features[?(\@.attributes.LAN_ew_GEN in ['Hessen', 'Niedersachsen'])]"), concat(count(),'_cases7_bl_per_100k'), property('attributes.cases7_bl_per_100k'));
multi(jsonPath("\$.features[?(\@.attributes.LAN_ew_GEN in ['Hessen', 'Niedersachsen'])]"), concat(count(),'_deaths'), property('attributes.Death'));
multi(jsonPath("\$.features[?(\@.attributes.LAN_ew_GEN in ['Hessen', 'Niedersachsen'])]"), concat(count(),'_lastUpdate'), property('attributes.Aktualisierung'));
   room       CoViD-19
   stateFormat {    my $ret = "<div style=\"text-align: left;\">";
    $ret .= "last <a href=\"https://corona.rki.de\" title=\"RKI CoViD19\" rel=\"noopener noreferrer\" target=\"_blank\">RKI CoViD-19</a> check => ";
    $ret .= POSIX::strftime("%d.%m. %H:%M",localtime(time_str2num(ReadingsTimestamp($name,".computedReadings","2000-01-01 00:00:00"))));
    $ret .= "<br \/>";
    $ret .= ReadingsVal($name,"0_name","-").":&nbsp;";
        $ret .= "<font style=\"font-weight:bold;color:";
            if(ReadingsNum($name,"0_cases7_bl_per_100k",0) < 35) {
                $ret .= "green";
            } elsif (ReadingsNum($name,"0_cases7_bl_per_100k",0) < 50) {
                $ret .= "orange";
            } else {
                $ret .= "red";
            }
        $ret .= ";\">".sprintf("%.1f", ReadingsNum($name,"0_cases7_bl_per_100k",0))."</font>&nbsp;&amp;&nbsp;";
        $ret .= "<font style=\"color:orange;font-weight:bold;\">".ReadingsVal($name,"0_cases","-")." F&auml;lle</font>&nbsp;&amp;&nbsp;";
        $ret .= "<font style=\"color:red;font-weight:bold;\">".ReadingsVal($name,"0_deaths","-")." Tote</font>";
        $ret .= "&nbsp;(".ReadingsVal($name,"0_lastUpdatedh","-").")<br \/>";
    $ret .= ReadingsVal($name,"1_name","-").":&nbsp;";
        $ret .= "<font style=\"font-weight:bold;color:";
            if(ReadingsNum($name,"1_cases7_bl_per_100k",0) < 35) {
                $ret .= "green";
            } elsif (ReadingsNum($name,"1_cases7_bl_per_100k",0) < 50) {
                $ret .= "orange";
            } else {
                $ret .= "red";
            }
        $ret .= ";\">".sprintf("%.1f", ReadingsNum($name,"1_cases7_bl_per_100k",0))."</font>&nbsp;&amp;&nbsp;";
        $ret .= "<font style=\"color:orange;font-weight:bold;\">".ReadingsVal($name,"1_cases","-")." F&auml;lle</font>&nbsp;&amp;&nbsp;";
        $ret .= "<font style=\"color:red;font-weight:bold;\">".ReadingsVal($name,"1_deaths","-")." Tote</font>";
        $ret .= "&nbsp;(".ReadingsVal($name,"1_lastUpdatedh","-").")";
    $ret .= "</div>";
    return $ret;}
   update-on-start 1
   userReadings 0_lastUpdatedh {POSIX::strftime ("%d.%m. %H:%M", localtime(ReadingsVal($name,"0_lastUpdate",0)/1000));}, 1_lastUpdatedh {POSIX::strftime ("%d.%m. %H:%M", localtime(ReadingsVal($name,"1_lastUpdate",0)/1000));}
   webCmd     reread
Wie gesagt, es tritt unregelmässig auf und ich kann es nicht reproduzieren.
Durch regelmässige FHEM-Updates wird FHEM ca 1x pro Woche sowieso neu gestartet (via shutdown -restart)

Wie kann ich hier weiter debuggen und den Fehler eingrenzen?
Stacktrace einschalten und verbose auf 5 setzen würde mir den log vollmüllen - aber wird dies wirklich hilfreich sein wenn der nächste Absturz/Neustart passiert ist?

Über ein Stups in die richtige Richtung bin ich dankbar.

EDIT 2023-04-20: ggf gefixt => https://forum.fhem.de/index.php?topic=133135.msg1272731#msg1272731

[rudolfkoenig]

status=11/SEGV bedeutet einen Fehler im perl Binary oder einen der verwendeten Bibliotheken. Um es zu lokalisieren wuerde ich mit "attr global verbose 5" anfangen.
Nach so einem Abbruch wird ueblicherweise ein core geschrieben, einem Programmierer mit Perl-Quellen und einem Debugger kann das auch helfen. Fraglich ist, ob man das Problem nach dem Lokalisieren einfach beheben kann (wir via Workaround im FHEM, die perl Maintainer via Bugfix).

Falls Du dazu keine Motivation verspuerst, dann empfehle ich eine andere (neuere?) Perl-Version zu testen.
Oder statt JsonMod "meine" Alternative mit at+HttpUtils_NonblockingGet+json2reading+hashKeyRename  zu verwenden.

[yersinia]

status=11/SEGV bedeutet einen Fehler im perl Binary oder einen der verwendeten Bibliotheken. Um es zu lokalisieren wuerde ich mit "attr global verbose 5" anfangen.
Nach so einem Abbruch wird ueblicherweise ein core geschrieben, einem Programmierer mit Perl-Quellen und einem Debugger kann das auch helfen.

Klingt logisch. Nur finde ich kein coredump-file für den perl prozess - ich bin auch etwas ratlos, wo ich überhaupt suchen müsste. Ich vermute, dass dies auch gar nicht aktiviert ist in der Standardinstallation von RaspiOS.

Wie gesagt, verbose = 5 lässt den log voll laufen - und ich frag mich, ob das dann förderlich ist dann.
Und perl 5.28.1-6 ist die aktuellste, verfügbare für RasPiOS Buster.

Code Auswählen Erweitern

perl:
  Installiert:           5.28.1-6
  Installationskandidat: 5.28.1-6
  Versionstabelle:
*** 5.28.1-6 500
        500 http://raspbian.raspberrypi.org/raspbian buster/main armhf Packages
        100 /var/lib/dpkg/status

[rudolfkoenig]

Und perl 5.28.1-6 ist die aktuellste, verfügbare für RasPiOS Buster.

Mit einem Compiler und etwas Geduld muesste man auch was Neueres bauen koennen.
Alternativ waehlt man eine andere Distribution. Archlinux soll ziemlich aktuelle Perl Versionen anbieten.

[yersinia]

Alternativ waehlt man eine andere Distribution. Archlinux soll ziemlich aktuelle Perl Versionen anbieten.

Ja, derzeit 5.32.1-1. Aber das FHEM system jetzt auf Arch umzuziehen - so groß ist der Schmerz noch nicht. Zumal weiss ich nicht, ob eine neuere Perl-Version nicht noch andere Löcher aufreisst...

Ok, dann belasse ich es erstmal dabei und werde beobachten....

[herrmannj]

@rudi irgendwann musst du deine jsonmod Aversion Mal ablegen. Masochismus kannst du auch anders ausleben

Der zeitliche Zusammenhang macht natürlich nachdenklich. Allerdings habe ich auch keine spontane Eingebung. Exotische Bibliotheken oder Techniken nehme ich nicht. Was ich sowieso Mal machen wollte ist die Default Json lib auf cpanel umzustellen. Wenn du möchtest kannst du das vmtl in der source auch selber fix.

Ob die Aufrufe komplett kompatibel sind müsste man testen, sollte eigentlich. Sonst halt zurück spielen.

Beim Perl würde ich eher über Perlbrew gegen. Da kann man die Versionen doch Recht komfortabel wechseln.

Vg
Joerg

[yersinia]

So, nach einer Weile stabilen Laufs ist FHEM heute morgen wieder nach SEGV neugestartet worden. Updatestand ist das release von gestern.
journalctl:

Code Auswählen Erweitern

Apr 10 06:09:00 raspi4 systemd[1]: fhem.service: Main process exited, code=killed, status=11/SEGV
Apr 10 06:09:00 raspi4 systemd[1]: fhem.service: Failed with result 'signal'.
Apr 10 06:09:01 raspi4 systemd[1]: fhem.service: Service RestartSec=100ms expired, scheduling restart.
Apr 10 06:09:01 raspi4 systemd[1]: fhem.service: Scheduled restart job, restart counter is at 13.
Apr 10 06:09:01 raspi4 systemd[1]: Stopped FHEM Home Automation.
Apr 10 06:09:01 raspi4 systemd[1]: Starting FHEM Home Automation...
Apr 10 06:09:01 raspi4 systemd[1]: Started FHEM Home Automation.

Da bisher alle Zeitpunkte mit einem Device zusammenhängen, habe ich genau dieses mal auf verbose 5 gesetzt. Anbei der logauszug um den Zeitpunkt herum:

Code Auswählen Erweitern

2021.04.10 06:04:20 1: ERROR: Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.10 06:04:20 1: stacktrace:
2021.04.10 06:04:20 1:     main::HttpUtils_NonblockingGet      called by FHEM/HttpUtils.pm (889)
2021.04.10 06:04:20 1:     main::HttpUtils_ParseAnswer         called by FHEM/HttpUtils.pm (642)
2021.04.10 06:04:20 1:     main::__ANON__                      called by fhem.pl (770)
2021.04.10 06:04:20 2: [dnscrypt_proxy_version] http request error: Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.10 06:09:00 4: [coronaSpreadDE] start request
2021.04.10 06:09:00 4: [coronaSpreadDE] next request: 2021.04.10 09:09:00
2021.04.10 06:09:00 5: HttpUtils url=https://services7.arcgis.com/mOBPykOjAyBO2ZKk/arcgis/rest/services/Coronaf%C3%A4lle_in_den_Bundesl%C3%A4ndern/FeatureServer/0/query?where=1%3D1&outFields=LAN_ew_GEN,Fallzahl,Aktualisierung,faelle_100000_EW,cases7_bl_per_100k,Death&returnGeometry=false&outSR=4326&f=json
2021.04.10 06:09:00 4: [coronaSpreadDE] start request
2021.04.10 06:09:00 4: [coronaSpreadDE] next request: 2021.04.10 09:09:00
2021.04.10 06:09:00 4: IP: services7.arcgis.com -> 13.225.74.43
2021.04.10 06:09:00 5: HttpUtils request header:
GET /mOBPykOjAyBO2ZKk/arcgis/rest/services/Coronaf%C3%A4lle_in_den_Bundesl%C3%A4ndern/FeatureServer/0/query?where=1%3D1&outFields=LAN_ew_GEN,Fallzahl,Aktualisierung,faelle_100000_EW,cases7_bl_per_100k,Death&returnGeometry=false&outSR=4326&f=json HTTP/1.0
Host: services7.arcgis.com
User-Agent: fhem
Accept-Encoding: gzip,deflate

Accept: application/json
Accept-Charset: utf-8, iso-8859-1

2021.04.10 06:09:00 4: https://services7.arcgis.com/mOBPykOjAyBO2ZKk/arcgis/rest/services/Coronaf%C3%A4lle_in_den_Bundesl%C3%A4ndern/FeatureServer/0/query?where=1%3D1&outFields=LAN_ew_GEN,Fallzahl,Aktualisierung,faelle_100000_EW,cases7_bl_per_100k,Death&returnGeometry=false&outSR=4326&f=json: HTTP response code 200
2021.04.10 06:09:00 5: HttpUtils https://services7.arcgis.com/mOBPykOjAyBO2ZKk/arcgis/rest/services/Coronaf%C3%A4lle_in_den_Bundesl%C3%A4ndern/FeatureServer/0/query?where=1%3D1&outFields=LAN_ew_GEN,Fallzahl,Aktualisierung,faelle_100000_EW,cases7_bl_per_100k,Death&returnGeometry=false&outSR=4326&f=json: Got data, length: 3999
2021.04.10 06:09:00 5: HttpUtils response header:
HTTP/1.1 200 OK
Content-Type: text/plain; charset=utf-8
Content-Length: 3999
Connection: close
Cache-Control: public, max-age=3600, s-maxage=3600
Last-Modified: Sat, 10 Apr 2021 01:34:14 GMT
ETag: sd2_-1224588352
Server: Microsoft-IIS/10.0
x-esri-query-request-units: 2
X-ArcGIS-Correlation-Id: |72a2606750218e4da5ac99877ff2267e.d102f39d_
X-ArcGIS-Instance: MTSDS_Web_IN_8
Strict-Transport-Security: max-age=63072000
X-Powered-By: ASP.NET
Access-Control-Allow-Origin: *
Date: Sat, 10 Apr 2021 04:08:00 GMT
X-Cache: Hit from cloudfront
Via: 1.1 27f665df26bde4a7226480b4a2890ff9.cloudfront.net (CloudFront)
X-Amz-Cf-Pop: FRA2-C2
X-Amz-Cf-Id: rVc8EYfV1CnbREaW9x9ctIpZQE6YsVab4elPZGppM88Wyq5GcwviKQ==
Age: 60
2021.04.10 06:09:00 4: [coronaSpreadDE] api encoding is utf-8, designated encoder is utf-8-strict
2021.04.10 06:09:01 1: Including fhem.cfg
2021.04.10 06:09:01 3: telnetPort: port 7072 opened
2021.04.10 06:09:01 3: WEB: port 8083 opened
2021.04.10 06:09:01 3: WEBphone: port 8084 opened
2021.04.10 06:09:01 3: WEBtablet: port 8085 opened

List des Devices siehe ersten post.

Vielleicht hilft dies irgendwie weiter. Ich habe weitere (CoViD-19 bezogene) JsonMod-Devices, die alle zu ähnlichen Zeiten triggern:
- 5 */1 * * * -> Stündlich um :05
- 9 */3 * * * -> alle durch 3 teilbare Stunden um :09 [das betroffene Device]
- 11 */3 * * * -> alle durch 3 teilbare Stunden um :11
- 12 */3 * * * -> alle durch 3 teilbare Stunden um :12

[herrmannj]

Hattest du Json Mal auf cpanel umgestellt? Sonst mach das

[Wasserwerk33]

Könnte mir jemand vielleicht sagen woran es nachher lag? An der covid Software oder woran? Habe das selbe Problem.

Danke für eure Hilfe

[yersinia]

Das lies sich nicht klären. Ich hab das verursachende JsonMod Device gelöscht und dann war Ruhe.

Mittlerweile habe ich das OS (Bullseye 32Bit -> 64Bit und Kernel 5.15.32), Perl Version (5.32.1) und die Inzidenzquelle gewechselt.

[yersinia]

Möglicherweise wurde die Ursache gefunden und gefixed: https://forum.fhem.de/index.php?topic=133135.msg1272731#msg1272731