- Platform information:
- Hardware: Raspberry Pi 3 Model B Rev 1.2
- OS: Linux 4.4.0-1-rpi2
- Java Runtime Environment: (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 1.8.0_152-b76)
- openHAB version: 2.2.0-1
- Issue of the topic: My events.log file stopped updating two days ago and items stopped updating in basic UI and switches stopped working. There’s a lot happening in the openhab.log around the time when it stopped updating.
Extract from last logs in events.log
2018-01-30 21:27:30.833 [ome.event.ItemCommandEvent] - Item 'HOUSE_POWER' received command ON
2018-01-30 21:27:34.254 [vent.ItemStateChangedEvent] - barometer changed from 1013.46 to 1013.41
2018-01-30 21:27:41.062 [ome.event.ItemCommandEvent] - Item 'HOUSE_POWER' received command ON
2018-01-30 21:27:51.118 [ome.event.ItemCommandEvent] - Item 'HOUSE_POWER' received command ON
2018-01-30 21:27:52.138 [hingStatusInfoChangedEvent] - 'verisure:lock:1:xxxxxxx' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-01-30 21:27:57.985 [vent.ItemStateChangedEvent] - systeminfo_computer_openHABianPi_cpu_load changed from 8.4 to 12.7
2018-01-30 21:27:58.033 [vent.ItemStateChangedEvent] - systeminfo_computer_openHABianPi_memory_availablePercent changed from 1.8 to 1.3
2018-01-30 21:28:01.407 [ome.event.ItemCommandEvent] - Item 'HOUSE_POWER' received command ON
2018-01-30 21:28:11.505 [vent.ItemStateChangedEvent] - bryggers_temp changed from 19.18 to 19.16
2018-01-30 21:28:11.567 [vent.ItemStateChangedEvent] - vaerksted_hum changed from 45.70 to 46.10
2018-01-30 21:28:11.700 [ome.event.ItemCommandEvent] - Item 'HOUSE_POWER' received command ON
2018-01-30 21:28:13.032 [hingStatusInfoChangedEvent] - 'verisure:lock:1:xxxxxxx' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-01-30 21:28:13.217 [hingStatusInfoChangedEvent] - 'verisure:lock:1:yyyyyyy' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-01-30 21:28:13.832 [hingStatusInfoChangedEvent] - 'verisure:lock:1:zzzzzzz' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-01-30 21:28:16.877 [vent.ItemStateChangedEvent] - RFLinkRaw changed from 20;80;Firstline;ID=001f;TEMP=00d4;
to 20;81;Firstline;ID=001f;TEMP=00d4;
2018-01-30 21:28:22.436 [ome.event.ItemCommandEvent] - Item 'HOUSE_POWER' received command ON
2018-01-30 21:28:24.045 [hingStatusInfoChangedEvent] - 'verisure:lock:1:yyyyyyy' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-01-30 21:29:13.980 [hingStatusInfoChangedEvent] - 'verisure:lock:1:zzzzzzz' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-01-30 21:29:44.412 [hingStatusInfoChangedEvent] - 'verisure:bridge:1' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE
2018-01-30 21:29:44.620 [hingStatusInfoChangedEvent] - 'verisure:bridge:1' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
Note: The Communication error happens every time the bridge logs out of Verisure…
Extracts from openhab.log at the time of the incident:
2018-01-30 21:17:51.055 [DEBUG] [risure.handler.VerisureBridgeHandler] - VerisureBridgeHandler - Thread is up and running!
2018-01-30 21:17:51.065 [DEBUG] [ng.verisure.internal.VerisureSession] - areWeLoggedIn() - Checking if we are logged in
2018-01-30 21:17:51.603 [DEBUG] [ng.verisure.internal.VerisureSession] - areWeLoggedIn(200) -
2018-01-30 21:17:51.605 [DEBUG] [ng.verisure.internal.VerisureSession] - Status code 200. Probably logged in
2018-01-30 21:17:51.608 [DEBUG] [ng.verisure.internal.VerisureSession] - VerisureSession:updateStatus
2018-01-30 21:17:51.718 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[{"date":"Today 18:42","disarmed":false,"notAllowedReason":"","image":"locked","operational":true,"changeAllowed":true,"label":"Locked","type":"DOOR_LOCK","name":"","location":"Hoveddør","id":"xxxxxxx","secureMode":false,"status":"locked"},{"date":"Yesterday 22:36","disarmed":false,"notAllowedReason":"","image":"locked","operational":true,"changeAllowed":true,"label":"Locked","type":"DOOR_LOCK","name":"","location":"Kælder","id":"yyyyyyy","secureMode":false,"status":"locked"},{"date":"Today 20:00","disarmed":false,"notAllowedReason":"","image":"locked","operational":true,"changeAllowed":true,"label":"Locked","type":"DOOR_LOCK","name":"","location":"Terrassedør","id":"zzzzzzz","secureMode":false,"status":"locked"}]
2018-01-30 21:18:11.467 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[]
2018-01-30 21:18:11.471 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:18:11.550 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:
2018-01-30 21:18:11.553 [INFO ] [ng.verisure.internal.VerisureSession] - Wrong response type null for call to https://mypages.verisure.com/settings/doorwindow?_=1517343491475
2018-01-30 21:18:11.561 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:18:11.656 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[]
2018-01-30 21:18:11.662 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:18:11.757 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[]
2018-01-30 21:18:11.762 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:27:51.055 [DEBUG] [risure.handler.VerisureBridgeHandler] - VerisureBridgeHandler - Thread is up and running!
2018-01-30 21:27:51.105 [DEBUG] [ng.verisure.internal.VerisureSession] - areWeLoggedIn() - Checking if we are logged in
2018-01-30 21:27:51.958 [DEBUG] [ng.verisure.internal.VerisureSession] - areWeLoggedIn(200) -
2018-01-30 21:27:51.992 [DEBUG] [ng.verisure.internal.VerisureSession] - Status code 200. Probably logged in
2018-01-30 21:27:51.995 [DEBUG] [ng.verisure.internal.VerisureSession] - VerisureSession:updateStatus
2018-01-30 21:27:52.123 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[{"date":"Today 18:42","disarmed":false,"notAllowedReason":"","image":"locked","operational":true,"changeAllowed":true,"label":"Locked","type":"DOOR_LOCK","name":"","location":"Hoveddør","id":"xxxxxxx","secureMode":false,"status":"locked"},{"date":"Yesterday 22:36","disarmed":false,"notAllowedReason":"","image":"locked","operational":true,"changeAllowed":true,"label":"Locked","type":"DOOR_LOCK","name":"","location":"Kælder","id":"yyyyyyy","secureMode":false,"status":"locked"},{"date":"Today 20:00","disarmed":false,"notAllowedReason":"","image":"locked","operational":true,"changeAllowed":true,"label":"Locked","type":"DOOR_LOCK","name":"","location":"Terrassedør","id":"zzzzzzz","secureMode":false,"status":"locked"}]
2018-01-30 21:28:11.900 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[]
2018-01-30 21:28:11.906 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:28:12.024 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:
2018-01-30 21:28:12.026 [INFO ] [ng.verisure.internal.VerisureSession] - Wrong response type null for call to https://mypages.verisure.com/settings/doorwindow?_=1517344091909
2018-01-30 21:28:12.028 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:28:12.141 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[]
2018-01-30 21:28:12.143 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:28:12.224 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[]
2018-01-30 21:28:12.226 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:28:32.225 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=48, service.id=161, service.bundleid=110, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.10.0.b1 [110])] due to timeout!
2018-01-30 21:28:33.154 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=48, service.id=161, service.bundleid=110, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.10.0.b1 [110])] due to timeout!
2018-01-30 21:28:33.358 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=48, service.id=161, service.bundleid=110, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.10.0.b1 [110])] due to timeout!
2018-01-30 21:28:33.364 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=48, service.id=161, service.bundleid=110, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.10.0.b1 [110])] due to timeout!
2018-01-30 21:31:58.598 [ERROR] [io.openhabcloud.internal.CloudClient] - Socket.IO error: {}
io.socket.engineio.client.EngineIOException: websocket error
at io.socket.engineio.client.Transport.onError(Transport.java:71) [225:org.openhab.io.openhabcloud:2.2.0]
at io.socket.engineio.client.transports.WebSocket.access$500(WebSocket.java:28) [225:org.openhab.io.openhabcloud:2.2.0]
at io.socket.engineio.client.transports.WebSocket$2$5.run(WebSocket.java:150) [225:org.openhab.io.openhabcloud:2.2.0]
at io.socket.thread.EventThread$2.run(EventThread.java:80) [225:org.openhab.io.openhabcloud:2.2.0]
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.io.EOFException
at okio.RealBufferedSource.require(RealBufferedSource.java:59) ~[?:?]
at okio.RealBufferedSource.readByte(RealBufferedSource.java:72) ~[?:?]
at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.java:115) ~[?:?]
at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.java:104) ~[?:?]
at okhttp3.internal.ws.RealWebSocket.readMessage(RealWebSocket.java:97) ~[?:?]
at okhttp3.ws.WebSocketCall.createWebSocket(WebSocketCall.java:152) ~[?:?]
at okhttp3.ws.WebSocketCall.access$000(WebSocketCall.java:41) ~[?:?]
at okhttp3.ws.WebSocketCall$1.onResponse(WebSocketCall.java:97) ~[?:?]
at okhttp3.RealCall$AsyncCall.execute(RealCall.java:126) ~[?:?]
at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32) ~[?:?]
... 3 more
2018-01-30 21:34:09.622 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = d6957f49-e659-4b15-b8b8-b6382543aabd, base URL = http://localhost:8080)
2018-01-30 21:34:16.001 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = d6957f49-e659-4b15-b8b8-b6382543aabd, base URL = http://localhost:8080)
2018-01-30 21:34:41.177 [ERROR] [io.openhabcloud.internal.CloudClient] - Socket.IO error: {}
io.socket.engineio.client.EngineIOException: xhr post error
at io.socket.engineio.client.Transport.onError(Transport.java:71) [225:org.openhab.io.openhabcloud:2.2.0]
at io.socket.engineio.client.transports.PollingXHR.access$000(PollingXHR.java:19) [225:org.openhab.io.openhabcloud:2.2.0]
at io.socket.engineio.client.transports.PollingXHR$4$1.run(PollingXHR.java:88) [225:org.openhab.io.openhabcloud:2.2.0]
at io.socket.thread.EventThread$2.run(EventThread.java:80) [225:org.openhab.io.openhabcloud:2.2.0]
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.io.IOException: 400
at io.socket.engineio.client.transports.PollingXHR$Request$1.run(PollingXHR.java:218) ~[?:?]
... 1 more
2018-01-30 21:34:41.205 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = d6957f49-e659-4b15-b8b8-b6382543aabd, base URL = http://localhost:8080)
2018-01-30 21:34:42.374 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = d6957f49-e659-4b15-b8b8-b6382543aabd, base URL = http://localhost:8080)
2018-01-30 21:35:32.906 [ERROR] [io.openhabcloud.internal.CloudClient] - Socket.IO error: {}
io.socket.engineio.client.EngineIOException: xhr post error
at io.socket.engineio.client.Transport.onError(Transport.java:71) [225:org.openhab.io.openhabcloud:2.2.0]
at io.socket.engineio.client.transports.PollingXHR.access$000(PollingXHR.java:19) [225:org.openhab.io.openhabcloud:2.2.0]
at io.socket.engineio.client.transports.PollingXHR$4$1.run(PollingXHR.java:88) [225:org.openhab.io.openhabcloud:2.2.0]
at io.socket.thread.EventThread$2.run(EventThread.java:80) [225:org.openhab.io.openhabcloud:2.2.0]
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.io.IOException: 502
at io.socket.engineio.client.transports.PollingXHR$Request$1.run(PollingXHR.java:218) ~[?:?]
... 1 more
2018-01-30 21:35:33.017 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = d6957f49-e659-4b15-b8b8-b6382543aabd, base URL = http://localhost:8080)
2018-01-30 21:35:34.453 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = d6957f49-e659-4b15-b8b8-b6382543aabd, base URL = http://localhost:8080)
2018-01-30 21:37:51.055 [DEBUG] [risure.handler.VerisureBridgeHandler] - VerisureBridgeHandler - Thread is up and running!
2018-01-30 21:37:51.086 [DEBUG] [ng.verisure.internal.VerisureSession] - areWeLoggedIn() - Checking if we are logged in
2018-01-30 21:37:51.736 [DEBUG] [ng.verisure.internal.VerisureSession] - areWeLoggedIn(200) -
2018-01-30 21:37:51.739 [DEBUG] [ng.verisure.internal.VerisureSession] - Status code 200. Probably logged in
2018-01-30 21:37:51.741 [DEBUG] [ng.verisure.internal.VerisureSession] - VerisureSession:updateStatus
2018-01-30 21:37:51.851 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[{"date":"Today 18:42","disarmed":false,"notAllowedReason":"","image":"locked","operational":true,"changeAllowed":true,"label":"Locked","type":"DOOR_LOCK","name":"","location":"Hoveddør","id":"xxxxxxx","secureMode":false,"status":"locked"},{"date":"Yesterday 22:36","disarmed":false,"notAllowedReason":"","image":"locked","operational":true,"changeAllowed":true,"label":"Locked","type":"DOOR_LOCK","name":"","location":"Kælder","id":"yyyyyyy","secureMode":false,"status":"locked"},{"date":"Today 20:00","disarmed":false,"notAllowedReason":"","image":"locked","operational":true,"changeAllowed":true,"label":"Locked","type":"DOOR_LOCK","name":"","location":"Terrassedør","id":"zzzzzzz","secureMode":false,"status":"locked"}]
2018-01-30 21:38:03.931 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[]
2018-01-30 21:38:03.938 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:38:04.016 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:
2018-01-30 21:38:04.018 [INFO ] [ng.verisure.internal.VerisureSession] - Wrong response type null for call to https://mypages.verisure.com/settings/doorwindow?_=1517344683942
2018-01-30 21:38:04.021 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:38:04.137 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[]
2018-01-30 21:38:04.140 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:38:04.199 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[]
2018-01-30 21:38:04.202 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:39:15.969 [WARN ] [okhttp3.OkHttpClient ] - A connection to https://myopenhab.org/ was leaked. Did you forget to close a response body?
2018-01-30 21:39:42.324 [WARN ] [okhttp3.OkHttpClient ] - A connection to https://myopenhab.org/ was leaked. Did you forget to close a response body?
2018-01-30 21:47:51.055 [DEBUG] [risure.handler.VerisureBridgeHandler] - VerisureBridgeHandler - Thread is up and running!
2018-01-30 21:47:51.079 [DEBUG] [ng.verisure.internal.VerisureSession] - areWeLoggedIn() - Checking if we are logged in
2018-01-30 21:47:51.655 [DEBUG] [ng.verisure.internal.VerisureSession] - areWeLoggedIn(200) -
2018-01-30 21:47:51.657 [DEBUG] [ng.verisure.internal.VerisureSession] - Status code 200. Probably logged in
2018-01-30 21:47:51.659 [DEBUG] [ng.verisure.internal.VerisureSession] - VerisureSession:updateStatus
2018-01-30 21:47:51.777 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[{"date":"Today 18:42","disarmed":false,"notAllowedReason":"","image":"locked","operational":true,"changeAllowed":true,"label":"Locked","type":"DOOR_LOCK","name":"","location":"Hoveddør","id":"xxxxxxx","secureMode":false,"status":"locked"},{"date":"Yesterday 22:36","disarmed":false,"notAllowedReason":"","image":"locked","operational":true,"changeAllowed":true,"label":"Locked","type":"DOOR_LOCK","name":"","location":"Kælder","id":"yyyyyyy","secureMode":false,"status":"locked"},{"date":"Today 20:00","disarmed":false,"notAllowedReason":"","image":"locked","operational":true,"changeAllowed":true,"label":"Locked","type":"DOOR_LOCK","name":"","location":"Terrassedør","id":"zzzzzzz","secureMode":false,"status":"locked"}]
2018-01-30 21:48:04.843 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[]
2018-01-30 21:48:04.848 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:48:04.903 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:
2018-01-30 21:48:04.905 [INFO ] [ng.verisure.internal.VerisureSession] - Wrong response type null for call to https://mypages.verisure.com/settings/doorwindow?_=1517345284850
2018-01-30 21:48:04.908 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:48:05.012 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[]
2018-01-30 21:48:05.014 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
2018-01-30 21:48:05.183 [DEBUG] [ng.verisure.internal.VerisureSession] - HTTP Response (200) Body:[]
2018-01-30 21:48:05.185 [DEBUG] [ng.verisure.internal.VerisureSession] - REST Response ({})
You can see a lot of logs from the verisure binding and they keep coming (I’ve disabled debug for it now though), but otherwise lots is happening around 21:28 - I just don’t know what to look for…
Bindings actively being used:
Samsung TV Binding 2.2.0
Sonos Binding 2.2.0
Systeminfo Binding 2.2.0
Verisure Bindning 2.3.0_3
Z-Wave Bindning 2.2.0
Serial Binding 1.11.0
SNMP Binding 1.11.0
MQTT Binding 1.11.0
I’m using the openHAB Cloud Connector 2.2.0 to gain access from my phone (I see a lot of drop outs though) and to get updates to an item from IFTTT.
I’m using MapDB Persistence 1.11.0 to make sure my items to update after time outs and restarts
JSONPath Transformation 2.2.0
Map Transformation 2.2.0
RegEx Transformation 2.2.0
VoiceRSS Text-to-Speech 2.2.0
Also I’m running Mosquitto MQTT on the same Rpi