Fehlermeldung Localhost Hyperion

[udo1toni]

Du setzt einfach mehrere logInfos zwischen die verschiedenen Befehle, z.B.

Code: Alles auswählen

logInfo("ambiOrange","orange {}",orange.toString)
Ambilight_Farbe.sendCommand(orange)
logInfo("ambiOrange","erfolgreich!")

Wenn nun der Fehler auftritt, steht unmittelbar vor der Fehlermeldung eine Zeile, aus der Du ersehen kannst, was nach Ambilight_Farbe geschickt wurde.
Eigentlich würde man solche log Befehle als logDebug() definieren, aber dann müsstest Du zusätzlich lernen, wie Du das Logging für Deine Rule auf DEBUG stellst...

[thedk]

Stimmt.
Habe überall die logInfo Zeilen eingefügt. Ich werde bereichten. Mal schauen wie lange es dieses mal dauert.

[thedk]

Komischerweise habe ich heute keinen Fehler im Log.

[udo1toni]

Mal wieder typisch...

Was ich mir vorstellen könnte, ist, dass es vereinzelt zu Timing Problemen kommt. Das könnte durch das Log beeinflusst werden. Aber warten wir erst mal ab...

[thedk]

Fehler sind wieder da!
Aber zu hauf und komplett ohne Zusammhang mit Hyperion, allerdings treten die Fehler wieder so oft auf, dass ich gar nicht bis zum Anfang vom Log komme, als der Fehler zum ersten mal aufgetreten ist.
Kann ich mir irgendwie das komplette Logfile anschauen vom, bspw. ganzem Tag? Die Fehler treten so oft auf, dass ich nur bis 19:44 schauen kann.

[udo1toni]

Aber sicher! Das Log liegt in /var/log/openhab2/ und heißt openhab.log.

[thedk]

Joa. Das Logfile ist einfach nur voll mit Fehlermeldung.
Konnte demnach immernoch nichts genaueres finden.

[thedk]

Erwischt!

Code: Alles auswählen

20:59:49.887 [INFO ] [ipse.smarthome.model.script.ambifarbe] - sende Kommando orange
20:59:49.893 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'Ambilight_Farbe' received command 35,100,100
20:59:49.893 [INFO ] [ipse.smarthome.model.script.ambifarbe] - erfolgreich
20:59:49.898 [INFO ] [pse.smarthome.model.script.ambiorange] - poste Update ON
20:59:49.905 [INFO ] [pse.smarthome.model.script.ambiorange] - erfolgreich
20:59:49.909 [INFO ] [smarthome.event.ItemStateChangedEvent] - Ambilight_Farbe changed from NULL to 35,100,100
20:59:49.912 [INFO ] [smarthome.event.ItemStateChangedEvent] - Ambilight_orange changed from OFF to ON
20:59:49.919 [INFO ] [ipse.smarthome.model.script.ambifarbe] - sende Kommando orange
20:59:49.925 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'Ambilight_Farbe' received command 35,100,100
20:59:49.925 [INFO ] [ipse.smarthome.model.script.ambifarbe] - erfolgreich
20:59:52.395 [ERROR] [ding.hyperion.handler.HyperionHandler] - java.lang.NumberFormatException: Expected an int but was 4294966001 at line 1 column 4718 path $.info.priorities[1].duration_ms
com.google.gson.JsonSyntaxException: java.lang.NumberFormatException: Expected an int but was 4294966001 at line 1 column 4718 path $.info.priorities[1].duration_ms
        at com.google.gson.internal.bind.TypeAdapters$7.read(TypeAdapters.java:245) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.TypeAdapters$7.read(TypeAdapters.java:235) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:129) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:220) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.TypeAdapterRuntimeTypeWrapper.read(TypeAdapterRuntimeTypeWrapper.java:41) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.CollectionTypeAdapterFactory$Adapter.read(CollectionTypeAdapterFactory.java:82) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.CollectionTypeAdapterFactory$Adapter.read(CollectionTypeAdapterFactory.java:61) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:129) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:220) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:129) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:220) [22:com.google.gson:2.7.0]
        at com.google.gson.Gson.fromJson(Gson.java:887) [22:com.google.gson:2.7.0]
        at com.google.gson.Gson.fromJson(Gson.java:852) [22:com.google.gson:2.7.0]
        at com.google.gson.Gson.fromJson(Gson.java:801) [22:com.google.gson:2.7.0]
        at com.google.gson.Gson.fromJson(Gson.java:773) [22:com.google.gson:2.7.0]
        at org.openhab.binding.hyperion.handler.HyperionHandler.sendCommand(HyperionHandler.java:311) [213:org.openhab.binding.hyperion:2.1.0.201706122125]
        at org.openhab.binding.hyperion.handler.HyperionHandler$1.run(HyperionHandler.java:81) [213:org.openhab.binding.hyperion:2.1.0.201706122125]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.lang.NumberFormatException: Expected an int but was 4294966001 at line 1 column 4718 path $.info.priorities[1].duration_ms
        at com.google.gson.stream.JsonReader.nextInt(JsonReader.java:1164) ~[?:?]
        at com.google.gson.internal.bind.TypeAdapters$7.read(TypeAdapters.java:243) ~[?:?]
        ... 23 more
20:59:53.530 [INFO ] [smarthome.event.ItemStateChangedEvent] - Leistungssteckdose_2_Vebrauch changed from 31638.299988 to 31638.50
20:59:53.546 [INFO ] [smarthome.event.ItemStateChangedEvent] - Leistungssteckdose_2_Strom changed from 338.00 to 486.00
20:59:53.550 [INFO ] [smarthome.event.ItemStateChangedEvent] - Leistungssteckdose_2_Leistung changed from 71.98 to 104.88
20:59:53.555 [INFO ] [smarthome.event.ItemStateChangedEvent] - Leistungssteckdose_2_Spannung changed from 230.30 to 229.40
20:59:56.251 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'ClearSwitch' received command ON
20:59:56.259 [INFO ] [smarthome.event.ItemStateChangedEvent] - ClearSwitch changed from NULL to ON
20:59:56.271 [INFO ] [smarthome.event.ItemStateChangedEvent] - ClearSwitch changed from ON to OFF
20:59:59.510 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'ClearSwitch' received command OFF
21:00:07.437 [INFO ] [smarthome.event.ItemStateChangedEvent] - Ambilight_Farbe changed from 35,100,100 to NULL
21:00:07.454 [INFO ] [pse.smarthome.model.script.ambiorange] - poste Update AUS
21:00:07.463 [INFO ] [pse.smarthome.model.script.ambiorange] - erfolgreich
21:00:07.473 [INFO ] [smarthome.event.ItemStateChangedEvent] - Ambilight_orange changed from ON to OFF
21:00:07.486 [INFO ] [ipse.smarthome.model.script.ambifarbe] - Ambi ausschalten
21:00:07.496 [INFO ] [ipse.smarthome.model.script.ambifarbe] - erfolgreich
21:00:07.496 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'Ambilight_Farbe' received command 0,0,0
21:00:07.509 [INFO ] [smarthome.event.ItemStateChangedEvent] - Ambilight_Farbe changed from NULL to 0,0,0
21:00:22.464 [ERROR] [ding.hyperion.handler.HyperionHandler] - java.lang.NumberFormatException: Expected an int but was 4294953380 at line 1 column 4642 path $.info.priorities[1].duration_ms
com.google.gson.JsonSyntaxException: java.lang.NumberFormatException: Expected an int but was 4294953380 at line 1 column 4642 path $.info.priorities[1].duration_ms
        at com.google.gson.internal.bind.TypeAdapters$7.read(TypeAdapters.java:245) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.TypeAdapters$7.read(TypeAdapters.java:235) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:129) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:220) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.TypeAdapterRuntimeTypeWrapper.read(TypeAdapterRuntimeTypeWrapper.java:41) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.CollectionTypeAdapterFactory$Adapter.read(CollectionTypeAdapterFactory.java:82) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.CollectionTypeAdapterFactory$Adapter.read(CollectionTypeAdapterFactory.java:61) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:129) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:220) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:129) [22:com.google.gson:2.7.0]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:220) [22:com.google.gson:2.7.0]
        at com.google.gson.Gson.fromJson(Gson.java:887) [22:com.google.gson:2.7.0]
        at com.google.gson.Gson.fromJson(Gson.java:852) [22:com.google.gson:2.7.0]
        at com.google.gson.Gson.fromJson(Gson.java:801) [22:com.google.gson:2.7.0]
        at com.google.gson.Gson.fromJson(Gson.java:773) [22:com.google.gson:2.7.0]
        at org.openhab.binding.hyperion.handler.HyperionHandler.sendCommand(HyperionHandler.java:311) [213:org.openhab.binding.hyperion:2.1.0.201706122125]
        at org.openhab.binding.hyperion.handler.HyperionHandler$1.run(HyperionHandler.java:81) [213:org.openhab.binding.hyperion:2.1.0.201706122125]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.lang.NumberFormatException: Expected an int but was 4294953380 at line 1 column 4642 path $.info.priorities[1].duration_ms
        at com.google.gson.stream.JsonReader.nextInt(JsonReader.java:1164) ~[?:?]
        at com.google.gson.internal.bind.TypeAdapters$7.read(TypeAdapters.java:243) ~[?:?]
        ... 23 more

Anfangen kann ich trotzdem mit nichts. Vielleicht kann mir jemand was zu sagen?

[udo1toni]

Also, was zunächst auffällt, ist, dass die Rule offensichtlich mehrfach gestartet wird, das kann schon für sich Probleme verursachen.
Der eigentliche Fehler folgt aber erst zweieinhalb Sekunden später.
Ich hab gerade mal im Sourcecode gestöbert, und ich finde sowohl das Wort priorities als auch das Wort duration_ms innerhalb einer Datei die zum hyperion Binding gehört.

Das Eine wäre also vermutlich, die Rule so umzustricken, dass sie nicht innerhalb Millisekunden mehrfach aufgerufen wird. Das Andere wäre einen Issue dazu aufzumachen.

[thedk]

Die Rule wird allerdings nicht mehrfach aufgerufen. Wüsste zumindest nicht wieso.