System-Crash nach Veränderung einer Sitemap-Einstellung

[Mercur]

Ich benutze das Landroid-Binding zur Steuerung des Worx-Rasen-Roboters mit der OH-App.

Wenn ich z.B. die Mähzeit per Slider verändern will, stürzt das gesamte Openhab-System ab
Die OH-App zeigt "Not network connection" Http-Error 404. Im Log sind alle items aller Bindings (homematic, zwave, landroid, Pushover, openweather usw.) resettet and nach einer Weile (ca. 30 sec) inititialisieren sie sich und sind wieder online. Auch die Verbindung zur Sidemap steht wieder.

In den Logs sind keine Auffälligkeiten vorhanden, außer dem Systemstart.
Der Fehler tritt sowohl bei OH 3.4.2 als auch bei 3.4.4 auf.

Mein System ist Standard-Openhabian auf Raspi 4, Die Landroid items and sitemap wurde 1:1 von der Binding-Doku übernommen.

Der Entwickler des Landroid-Bindings weiß leider auch keinen Rat.

Bei Bedienung anderer Sitemaps (Heizung, Rolladen usw.) tritt der Fehler nicht auf !

Wie kann man das Problem eingrenzen ?

[J-N-K]

Es steht wirklich gar nichts im Log? Und was heisst "resettet"? UNDEF? NULL?

[Mercur]

event.log beginnt so:
2023-05-22 11:05:26.118 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HmIP-SWDO-PL:3014F711A0001F5A4993DDC5:0023DD89A4E698' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2023-05-22 11:05:26.891 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'pushover:pushover-account:account' changed from UNINITIALIZED to INITIALIZING
2023-05-22 11:05:26.973 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'pushover:pushover-account:account' changed from INITIALIZING to UNKNOWN
2023-05-22 11:05:26.981 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HmIP-PSM-2:3014F711A0001F5A4993DDC5:0034DF29A37776' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2023-05-22 11:05:27.007 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HmIP-PCBS:3014F711A0001F5A4993DDC5:00045D89ACEF28' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2023-05-22 11:05:27.021 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HmIP-eTRV-2:3014F711A0001F5A4993DDC5:000A1D899056AF' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2023-05-22 11:05:27.041 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HmIP-RCV-50:3014F711A0001F5A4993DDC5:HmIP-RCV-1' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2023-05-22 11:05:27.048 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HmIP-eTRV-2:3014F711A0001F5A4993DDC5:000A1D89905D52' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2023-05-22 11:05:27.051 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'astro:sun:local' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to INITIALIZING
2023-05-22 11:05:27.107 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HmIP-SWDO-PL:3014F711A0001F5A4993DDC5:0023DD898E1B41' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)

openhab.log beginnt so:
2023-05-22 11:04:28.203 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Berlin'.
2023-05-22 11:04:28.293 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '48.5,7.9'.
2023-05-22 11:04:28.297 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'de_DE'.
2023-05-22 11:04:49.543 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Haus.items'
2023-05-22 11:04:50.344 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Schalter.items'
2023-05-22 11:04:50.406 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'landroid.items'
2023-05-22 11:04:50.916 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Garage.items'
2023-05-22 11:04:50.954 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Wetter_OneCall.items'
2023-05-22 11:04:51.658 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'landroid.persist'
2023-05-22 11:04:51.736 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'landroid.persist' has errors, therefore ignoring it: [1,1]: mismatched input 'MowerBat_Chart' expecting 'Strategies'

2023-05-22 11:04:52.615 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'landroid.sitemap'
2023-05-22 11:04:53.191 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'HausNeu.sitemap'
2023-05-22 11:04:53.753 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Pushover.things'
2023-05-22 11:04:53.826 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'landroid.things'
2023-05-22 11:05:02.904 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2023-05-22 11:05:03.501 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'WaschmaschineV2.rules'
2023-05-22 11:05:05.855 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'TrocknerV2.rules'
2023-05-22 11:05:06.524 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Alarme.rules'
2023-05-22 11:05:06.824 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Reload_Gateway.rules'
2023-05-22 11:05:07.105 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'landroid.rules'
2023-05-22 11:05:07.923 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Beleuchtung.rules'
2023-05-22 11:05:19.426 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.

[J-N-K]

Das heisst, openHAB startet komplett neu? Es müsste dann noch eine openhab.log.1 oder so ähnlich geben, mit dem vorherigen Log. Wie endet denn das?

[Mercur]

ja die gibt es.
Die eventslog 7 endet mit:
2023-05-22 11:00:11.002 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Robby' changed from Suche Kabel to Heimfahrt
2023-05-22 11:00:11.328 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'GATEWAYEXTRAS_ReloadAllFromGateway' changed from ON to OFF
2023-05-22 11:01:15.208 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidLastUpdate' changed from 2023-05-22T11:00:06.000+0200 to 2023-05-22T11:01:11.000+0200
2023-05-22 11:01:15.276 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidBatteryVoltage' changed from 18.27 to 18.64
2023-05-22 11:01:15.278 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidBatteryCharging' changed from OFF to ON
2023-05-22 11:01:15.279 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidPitch' changed from -2.4 to -0.1
2023-05-22 11:01:15.280 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidRoll' changed from 0.7 to 0.9
2023-05-22 11:01:15.281 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidYaw' changed from 357.9 to 349.6
2023-05-22 11:01:15.282 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidTotalBladeTime' changed from 11336 to 11337
2023-05-22 11:01:15.284 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidCurrentBladeTime' changed from 1203 to 1204
2023-05-22 11:01:15.285 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidTotalDistance' changed from 154519 m to 154532 m
2023-05-22 11:01:15.286 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidTotalTime' changed from 11422 to 11423
2023-05-22 11:01:15.295 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidStatusCode' changed from 30 to 1
2023-05-22 11:01:15.296 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidStatusDescription' changed from Going home to Home
2023-05-22 11:01:15.299 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Robby' changed from Heimfahrt to zu Hause
2023-05-22 11:03:05.500 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Akt_Leistung_Waschen' changed from 2.04 to 1.73
2023-05-22 11:03:55.362 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'LandroidOneTimeScheduleDuration' received command 180
2023-05-22 11:03:55.372 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'LandroidOneTimeScheduleDuration' predicted to become 180
2023-05-22 11:03:55.386 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidOneTimeScheduleDuration' changed from 0 to 180
2023-05-22 11:03:56.387 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'LandroidOneTimeScheduleDuration' received command 120
2023-05-22 11:03:56.392 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'LandroidOneTimeScheduleDuration' predicted to become 120
2023-05-22 11:03:56.396 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LandroidOneTimeScheduleDuration' changed from 180 to 120

und die openhablog 7 endet mit:
2023-05-22 11:00:10.084 [INFO ] [org.openhab.core.model.script.Robby ] - Sende Benachrichtigungen
2023-05-22 11:00:10.988 [INFO ] [org.openhab.core.model.script.Robby ] - Sende Benachrichtigungen
2023-05-22 11:01:15.297 [INFO ] [org.openhab.core.model.script.Robby ] - Sende Benachrichtigungen

aber der letzte Eintrag in der openhablog7 ist ja 4 Minuten vor dem Crash.
Ich kapier's nicht ...

[Mercur]

Habe noch etwas weiter gegraben...
im Syslog:
May 22 11:00:00 openhabian4 kernel: [1538770.225789] hwmon hwmon1: Undervoltage detected!
May 22 11:00:16 openhabian4 kernel: [1538786.353938] hwmon hwmon1: Voltage normalised
May 22 11:03:46 openhabian4 kernel: [1538996.022071] hwmon hwmon1: Undervoltage detected!
May 22 11:03:52 openhabian4 kernel: [1539002.070104] hwmon hwmon1: Voltage normalised
May 22 11:03:58 openhabian4 karaf[9095]: Exception in thread "Thread-92" com.google.gson.JsonSyntaxException: java.io.EOFException: End of input at line 1 column 842 path $.dat.modules.RL.dbg
May 22 11:03:58 openhabian4 karaf[9095]: #011at com.google.gson.internal.Streams.parse(Streams.java:59)
May 22 11:03:58 openhabian4 karaf[9095]: #011at com.google.gson.JsonParser.parseReader(JsonParser.java:102)
May 22 11:03:58 openhabian4 karaf[9095]: #011at com.google.gson.JsonParser.parseReader(JsonParser.java:70)
May 22 11:03:58 openhabian4 karaf[9095]: #011at com.google.gson.JsonParser.parseString(JsonParser.java:51)
May 22 11:03:58 openhabian4 karaf[9095]: #011at org.openhab.binding.worxlandroid.internal.WorxLandroidMowerHandler.processMessage(WorxLandroidMowerHandler.java:826)
May 22 11:03:58 openhabian4 karaf[9095]: #011at org.openhab.binding.worxlandroid.internal.mqtt.AWSTopic.onMessage(AWSTopic.java:58)
May 22 11:03:58 openhabian4 karaf[9095]: #011at org.openhab.binding.worxlandroid.internal.mqtt.AWSClient.lambda$1(AWSClient.java:192)
May 22 11:03:58 openhabian4 karaf[9095]: #011at software.amazon.awssdk.crt.mqtt.MqttClientConnection$MessageHandler.deliver(MqttClientConnection.java:48)
May 22 11:03:58 openhabian4 karaf[9095]: Caused by: java.io.EOFException: End of input at line 1 column 842 path $.dat.modules.RL.dbg
May 22 11:03:58 openhabian4 karaf[9095]: #011at com.google.gson.stream.JsonReader.nextNonWhitespace(JsonReader.java:1457)
May 22 11:03:58 openhabian4 karaf[9095]: #011at com.google.gson.stream.JsonReader.doPeek(JsonReader.java:491)
May 22 11:03:58 openhabian4 karaf[9095]: #011at com.google.gson.stream.JsonReader.hasNext(JsonReader.java:422)
May 22 11:03:58 openhabian4 karaf[9095]: #011at com.google.gson.internal.bind.TypeAdapters$28.read(TypeAdapters.java:779)
May 22 11:03:58 openhabian4 karaf[9095]: #011at com.google.gson.internal.bind.TypeAdapters$28.read(TypeAdapters.java:725)
May 22 11:03:58 openhabian4 karaf[9095]: #011at com.google.gson.internal.Streams.parse(Streams.java:49)
May 22 11:03:58 openhabian4 karaf[9095]: #011... 7 more
May 22 11:03:58 openhabian4 karaf[9095]: Fatal error condition occurred in /work/src/native/mqtt_connection.c:680: !aws_jni_check_and_clear_exception(env)
May 22 11:03:58 openhabian4 karaf[9095]: Exiting Application
May 22 11:03:58 openhabian4 karaf[9095]: No call stack information available
May 22 11:03:58 openhabian4 systemd[1]: openhab.service: Main process exited, code=killed, status=6/ABRT
May 22 11:03:58 openhabian4 systemd[1]: openhab.service: Failed with result 'signal'.
May 22 11:03:58 openhabian4 systemd[1]: openhab.service: Consumed 8min 15.371s CPU time.
May 22 11:04:03 openhabian4 systemd[1]: openhab.service: Scheduled restart job, restart counter is at 2.
May 22 11:04:03 openhabian4 systemd[1]: Stopping Frontail openHAB instance, reachable at http://openhabian4:9001...
May 22 11:04:03 openhabian4 systemd[1]: frontail.service: Succeeded.
May 22 11:04:03 openhabian4 systemd[1]: Stopped Frontail openHAB instance, reachable at http://openhabian4:9001.
May 22 11:04:03 openhabian4 systemd[1]: frontail.service: Consumed 2.130s CPU time.
May 22 11:04:03 openhabian4 systemd[1]: Stopped openHAB - empowering the smart home.
May 22 11:04:03 openhabian4 systemd[1]: openhab.service: Consumed 8min 15.371s CPU time.
May 22 11:04:03 openhabian4 systemd[1]: Started openHAB - empowering the smart home.
May 22 11:04:03 openhabian4 systemd[1]: Started Frontail openHAB instance, reachable at http://openhabian4:9001.
May 22 11:04:10 openhabian4 kernel: [1539020.214556] hwmon hwmon1: Undervoltage detected!
May 22 11:04:14 openhabian4 kernel: [1539024.246534] hwmon hwmon1: Voltage normalised
May 22 11:04:16 openhabian4 frontail[10487]: tail: '/var/log/openhab/openhab.log' has been replaced; following new file
May 22 11:04:16 openhabian4 frontail[10487]: tail: '/var/log/openhab/events.log' has been replaced; following new file
May 22 11:04:24 openhabian4 kernel: [1539034.326813] hwmon hwmon1: Undervoltage detected!
May 22 11:04:28 openhabian4 kernel: [1539038.358830] hwmon hwmon1: Voltage normalised
May 22 11:04:42 openhabian4 kernel: [1539052.471175] hwmon hwmon1: Undervoltage detected!
May 22 11:04:50 openhabian4 kernel: [1539060.535239] hwmon hwmon1: Voltage normalised
May 22 11:05:01 openhabian4 kernel: [1539070.615515] hwmon hwmon1: Undervoltage detected!
May 22 11:05:01 openhabian4 CRON[11113]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 22 11:05:05 openhabian4 kernel: [1539074.647516] hwmon hwmon1: Voltage normalised
May 22 11:05:09 openhabian4 kernel: [1539078.679699] hwmon hwmon1: Undervoltage detected!
May 22 11:05:28 openhabian4 karaf[10484]: RXTX Warning: Removing stale lock file. /var/lock/LCK..ttyUSB0
May 22 11:06:14 openhabian4 karaf[10484]: RXTX Warning: Removing stale lock file. /var/lock/LCK..ttyS0
May 22 11:06:32 openhabian4 dhcpcd[886]: eth0: Router Advertisement from fe80::7642:7fff:feaf:8e6a
May 22 11:06:33 openhabian4 kernel: [1539163.353151] hwmon hwmon1: Voltage normalised
May 22 11:09:29 openhabian4 kernel: [1539338.748605] hwmon hwmon1: Undervoltage detected!
May 22 11:09:33 openhabian4 kernel: [1539342.780639] hwmon hwmon1: Voltage normalised
May 22 11:10:01 openhabian4 kernel: [1539371.005283] hwmon hwmon1: Undervoltage detected!
May 22 11:10:15 openhabian4 kernel: [1539385.117418] hwmon hwmon1: Voltage normalised
May 22 11:11:52 openhabian4 dhcpcd[886]: eth0: Router Advertisement from fe80::7642:7fff:feaf:8e6a
May 22 11:11:53 openhabian4 dhcpcd[886]: eth0: Router Advertisement from fe80::7642:7fff:feaf:8e6a
May 22 11:15:01 openhabian4 CRON[11960]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 22 11:15:40 openhabian4 dhcpcd[886]: eth0: Router Advertisement from fe80::7642:7fff:feaf:8e6a
May 22 11:16:52 openhabian4 dhcpcd[886]: eth0: Router Advertisement from fe80::7642:7fff:feaf:8e6a
May 22 11:16:56 openhabian4 dhcpcd[886]: eth0: Router Advertisement from fe80::7642:7fff:feaf:8e6a
May 22 11:17:02 openhabian4 CRON[12153]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)

Warum der Raspi Unterspannung anmeckert ? Das Netzteil soll bis 4 A liefern. aber das kann ja wohl nicht der Grund für den Absturz sein, oder ?

[J-N-K]

Nein, das Problem ist:

Code: Alles auswählen

May 22 11:03:58 openhabian4 karaf[9095]: Exception in thread "Thread-92" com.google.gson.JsonSyntaxException: java.io.EOFException: End of input at line 1 column 842 path $.dat.modules.RL.dbg

Offensichtlich ist die Antwort vom Server kein JSON, unvollständiges JSON oder enthält unerwartete Daten. Passiert das reproduzierbar oder ist das einmalig passiert?

Ist kein offizielles Binding, oder? Ich wollte gerade mal in den Code gucken, aber ich finde es nicht.

[Mercur]

Das passiert bei jeder Änderung...
Das Landroid-Binding: https://github.com/nibi79/worxlandroid
Ich habe die aktuellste Version v3.4.1-beta 2023-04-09 installiert.

[J-N-K]

So ganz generell kann man sich natürlich fragen, warum man MQTT mit AWS implementiert (was letztlich zu diesem Crash führt), aber:

Code: Alles auswählen

    @Override
    public void processMessage(AWSMessageI message) {

        updateStatus(ThingStatus.ONLINE);

        JsonElement jsonElement = JsonParser.parseString(message.getPayload());

        if (jsonElement.isJsonObject()) {
            processStatusMessage(jsonElement.getAsJsonObject());
        }
    }

ist jetzt keine besonders gute Idee. Laut JavaDoc zu JsonParser.parseString muss man JSONParseException und JSONSyntaxException handlen, also eher so

Code: Alles auswählen

    @Override
    public void processMessage(AWSMessageI message) {
        updateStatus(ThingStatus.ONLINE);
        try {
            JsonElement jsonElement = JsonParser.parseString(message.getPayload());
            if (jsonElement.isJsonObject()) {
                processStatusMessage(jsonElement.getAsJsonObject());
            }
        } catch (JSONParseException | JSONSyntaxException e) {
            logger.warn("Received invalid JSON content '{}': {}", message.getPayload(), e.getMessage());
        }
    }

[Mercur]

@J-N-K
Danke für deine Info. Dein Einverständnis vorausgesetzt, habe ich diese in Github an den Autor des Bindings weitergeleitet, da meine Kenntnisse hierzu nicht ausreichen. Ich denke, er wird auf dich zukommen.
Falls nicht, werde ich dir berichten, wie es weitergegangen ist.