search

nibi79 / synologysurveillancestation

Synology Surveillancestation Binding
45 stars 5 forks source link

Motion detected always ON #14

Closed Danny89530 closed 6 years ago

Danny89530 commented 6 years ago

Hi, everything works fine with the only except of the Movement detection. If a camera detect a movement, the switch turns from OFF state to ON but, after that it not will return to OFF state.

Synology 1813+, DSM 6.1.4-15217 Update 5, Synology Surveillance Station 8.1.3-5473

Pavion commented 6 years ago

Hi there! This is a known issue of a previous version. Have you the last release already? The project is now under a heavy development and sadly some bugs are swarming.

Danny89530 commented 6 years ago

Hi @Pavion, I've downloaded the 0.15-alpha jar version on releases page. I've found your project just today, so that is the first installation. Let me know if i can help you with the issue, feel free to contact me for alfa/beta-testing, I'm very interessed on your great job ;)

Regards.

Danny89530 commented 6 years ago

Hello there, I've done another test right now, the switch has successfully changed its state, but the device goes OFFLINE before.

2018-01-01 21:35:43.383 [vent.ItemStateChangedEvent] - CAM_Roof_Event_EventDetected changed from OFF to ON
2018-01-01 21:35:53.086 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 21:35:55.087 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 21:36:49.309 [vent.ItemStateChangedEvent] - CAM_Roof_Event_EventDetected changed from ON to OFF

Both the server and the camera are connected with ethernet and there are no physical connection problems.

Hope it helps. Regards, Danny

Pavion commented 6 years ago

Hey, glad to have an interested person on board! Please feel free to create new issues. I actually need some more ideas I could implement. It's too boring to implement own ideas only :)

As for your problem: as such, it's common for motion event to take some time. The OFFLINE thing I can't understand yet. How often does it happens? From time to time? Every time on motion event? Just one time? Are there more events in between? What are your refresh rates? What channels are linked? If it happens often, you would see more output in Karaf.

Danny89530 commented 6 years ago

I've done several tests with 3 different cameras and the MotionEvent switch change his state now. Unfortunetly the CommunicationError is indipendent from the event, i think the switch don't change his status because of the apparent OFFLINE state of the camera at the moment of change.

This is the log of the past 20 min

2018-01-01 21:50:53.084 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 21:50:53.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 21:51:00.083 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 21:51:00.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 21:52:04.084 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 21:52:04.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 21:56:00.084 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 21:56:00.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 21:57:08.083 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 21:57:08.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 21:57:11.084 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 21:57:11.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 21:58:05.409 [vent.ItemStateChangedEvent] - CAM_Roof_Event_EventDetected changed from OFF to ON
2018-01-01 21:58:38.084 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 21:58:38.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 21:58:48.084 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 21:58:48.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 21:59:10.083 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 21:59:10.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 21:59:44.704 [vent.ItemStateChangedEvent] - CAM_Roof_Event_EventDetected changed from ON to OFF
2018-01-01 22:00:33.084 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 22:00:33.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 22:02:09.083 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 22:02:09.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 22:03:37.084 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 22:03:37.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 22:07:05.084 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 22:07:05.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 22:07:06.084 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 22:07:06.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 22:08:38.084 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 22:08:38.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 22:09:00.084 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 22:09:00.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 22:10:09.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
2018-01-01 22:10:11.085 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
2018-01-01 22:10:11.099 [hingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE

EDIT: For testing purpose i've linked just one channel (the event switch) on one camera: 0 on snapshot refresh rate, 1 second on events refresh rate

Sorry for my poor english.. Regards, Danny

Pavion commented 6 years ago

What are your refresh rates? It seems, you have an exception in one of the other threads, probably Enable/Record.

There are three threads (Snapshot, Enable/Record, Events), which could be cross-tested: Pressing Enable should enable/disable Snapshot Pressing Record should also trigger Manual Event (with delay)

In the Synology Surveillance Station under Live View you can also trigger a record. This should be reflected by both Record and Manual Event channels.

You can also unbind the corresponding channels and see if exception vanishes.

P.S. Where are you from?

Danny89530 commented 6 years ago

I'm writing from Italy. For testing purpose I've linked just one channel (the event switch) on just one camera.

I've tried access to karaf without success, can you guide me on the right direction?

Pavion commented 6 years ago

Oh, we'll stick to English then :)

One second? And you just get Exceptions every two minutes?! Could you perhaps decrease the rate to 2-3 seconds? It might be a concurrency issue.

As for Karaf:

Please answer if you need more details on this steps.

Danny89530 commented 6 years ago

My installation of OpenHAB is on a standalone VM under ESXi. I've found the karaf shell, thanks anyway :)

These are the exceptions:

22:47:48.045 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:station:1350lon000474' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
22:47:48.082 [ERROR] [station.internal.thread.SynoApiThread] - Error on refresh: {}
java.lang.IllegalStateException: Could not update status, because callback is missing
    at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateStatus(BaseThingHandler.java:424) [116:org.eclipse.smarthome.core.thing:0.10.0.b1]
    at org.openhab.binding.synologysurveillancestation.handler.SynoStationHandler.updateStatus(SynoStationHandler.java:183) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateStatus(BaseThingHandler.java:451) [116:org.eclipse.smarthome.core.thing:0.10.0.b1]
    at org.openhab.binding.synologysurveillancestation.handler.SynoStationHandler.updateStatus(SynoStationHandler.java:188) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThread.updateStatus(SynoApiThread.java:108) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThread.access$1(SynoApiThread.java:106) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThread$1.run(SynoApiThread.java:50) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    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) [?:?]
22:47:48.082 [ERROR] [on.internal.thread.SynoApiThreadEvent] - could not get event org.eclipse.smarthome.core.thing.internal.ThingImpl@c6dfe1d9: {}
java.lang.NullPointerException: null
    at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThreadEvent.refresh(SynoApiThreadEvent.java:47) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThread$1.run(SynoApiThread.java:49) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    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) [?:?]
22:47:48.118 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:station:1350lon000474' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
22:47:49.082 [ERROR] [on.internal.thread.SynoApiThreadEvent] - could not get event org.eclipse.smarthome.core.thing.internal.ThingImpl@c6dfe1d9: {}
java.lang.NullPointerException: null
    at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThreadEvent.refresh(SynoApiThreadEvent.java:47) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThread$1.run(SynoApiThread.java:49) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    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) [?:?]
22:47:49.171 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:station:1350lon000474' changed from INITIALIZING to ONLINE
22:47:49.186 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
22:47:49.189 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from INITIALIZING to ONLINE
22:47:50.082 [ERROR] [on.internal.thread.SynoApiThreadEvent] - could not get event org.eclipse.smarthome.core.thing.internal.ThingImpl@c6dfe1d9: {}
java.lang.NullPointerException: null
    at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThreadEvent.refresh(SynoApiThreadEvent.java:47) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThread$1.run(SynoApiThread.java:49) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    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) [?:?]
22:47:50.083 [ERROR] [station.internal.thread.SynoApiThread] - Error on refresh: {}
java.lang.IllegalStateException: Could not update status, because callback is missing
    at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateStatus(BaseThingHandler.java:424) [116:org.eclipse.smarthome.core.thing:0.10.0.b1]
    at org.openhab.binding.synologysurveillancestation.handler.SynoStationHandler.updateStatus(SynoStationHandler.java:183) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThread.updateStatus(SynoApiThread.java:110) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThread.access$1(SynoApiThread.java:106) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThread$1.run(SynoApiThread.java:50) [258:org.openhab.binding.synologysurveillancestation:2.2.0.a15]
    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) [?:?]
22:48:21.190 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
22:48:21.513 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE

Hope this helps :)

Danny89530 commented 6 years ago

Hey @Pavion, I've changed the refresh rate from 1 to 2 seconds, I've increased up 'til 5 secs with no success: the exceptions remains.

Another thing: After restarting the process I had to delete and re-add both the camera and the Bridge objects as the latter was no longer recognized online

Pavion commented 6 years ago

Latter issue I've encountered myself just now and try to fix it. As for the first one, i still can't find a beginning. Could you perhaps supply even larger chunk of your Karaf log? Your last chunk begins with: 22:47:48.045 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:station:1350lon000474' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR) and has some follow-up errors, I still need an exception, which caused the bridge to go offline: 'synologysurveillancestation:station:1350lon000474' changed from ONLINE to .... I hope you can provide some more info and I'll check on it tomorrow!

Danny89530 commented 6 years ago

Hi @Pavion, I'm trying to extract the log you've requested but unfortunetly the only events I've found are the following:

[...]
00:28:25.844 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514849308","total":0},"success":true}
00:28:27.563 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication error
00:28:28.024 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514849310","total":0},"success":true}
00:28:28.025 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Communication error to ONLINE
00:28:28.922 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514849311","total":0},"success":true}
[...]

These are the Karaf log levels:

openhab> log:get
Logger                                             │ Level
───────────────────────────────────────────────────┼──────
ROOT                                               │ WARN
javax.jmdns                                        │ ERROR
org.apache.karaf.jaas.modules.audit                │ INFO
org.apache.karaf.kar.internal.KarServiceImpl       │ ERROR
org.apache.karaf.shell.support                     │ OFF
org.eclipse.smarthome                              │ INFO
org.jupnp                                          │ ERROR
org.openhab                                        │ INFO
org.openhab.binding.synologysurveillancestation    │ TRACE
org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR
org.ops4j.pax.web.pax-web-runtime                  │ OFF
smarthome.event                                    │ DEBUG
smarthome.event.InboxUpdatedEvent                  │ ERROR
smarthome.event.ItemAddedEvent                     │ ERROR
smarthome.event.ItemRemovedEvent                   │ ERROR
smarthome.event.ItemStateEvent                     │ ERROR
smarthome.event.ThingAddedEvent                    │ ERROR
smarthome.event.ThingRemovedEvent                  │ ERROR
smarthome.event.ThingStatusInfoEvent               │ ERROR

Please tell me where can I find the requested informations.

Regards, Danny

Pavion commented 6 years ago

Most detailed information (exception log) is in real time in Karaf, as you've already sent me. The other important one is the openhab.log. Could you please try to find the entries from both just before the Bridge Thing synologysurveillancestation:camera:1350lon000474 (not the :14) goes OFFLINE? Anyway I'll see into it and try to add more logging tomorrow. Thanks so far :)

Pavion commented 6 years ago

Hi Danny, I've just drafted a new version, which should address some of the errors you've mentioned. Beside that, some extended logging is also implemented. If you still encounter errors, their origin should be tracked down easier. Please see the release' change log for installation tips.

Danny89530 commented 6 years ago

Hi @Pavion, I've installed the new package. I've stopped OpenHAB service, replaced the *.jar and started it again. The frequence of the errors is stightly reduced but unfortunatly, still remains.

The log is in TRACE mode, cleaned by personal information, the only events captured are, again, the _COMMUNICATIONERROR but no other events were tracked.

openhab> log:get
Logger                                             │ Level
───────────────────────────────────────────────────┼──────
ROOT                                               │ WARN
javax.jmdns                                        │ ERROR
org.apache.karaf.jaas.modules.audit                │ INFO
org.apache.karaf.kar.internal.KarServiceImpl       │ ERROR
org.apache.karaf.shell.support                     │ OFF
org.eclipse.smarthome                              │ INFO
org.jupnp                                          │ ERROR
org.openhab                                        │ INFO
org.openhab.binding.synologysurveillancestation    │ TRACE
org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR
org.ops4j.pax.web.pax-web-runtime                  │ OFF
smarthome.event                                    │ DEBUG
smarthome.event.InboxUpdatedEvent                  │ ERROR
smarthome.event.ItemAddedEvent                     │ ERROR
smarthome.event.ItemRemovedEvent                   │ ERROR
smarthome.event.ItemStateEvent                     │ ERROR
smarthome.event.ThingAddedEvent                    │ ERROR
smarthome.event.ThingRemovedEvent                  │ ERROR
smarthome.event.ThingStatusInfoEvent               │ ERROR

openhab> log:tail
[...]
22:23:04.808 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:station:1350lon000474' changed from UNINITIALIZED to INITIALIZING
22:23:05.858 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:station:1350lon000474' changed from INITIALIZING to OFFLINE (COMMUNICATION_ERROR): Errorcode: 0
22:23:05.894 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
22:23:05.897 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
22:23:05.915 [INFO ] [smarthome.event.ItemStateChangedEvent] - CAM_Roof_Event_EventDetected changed from NULL to OFF
22:23:06.234 [INFO ] [i.dashboard.internal.DashboardService] - Started dashboard at http://***.***.***.***:8080
22:23:06.235 [INFO ] [i.dashboard.internal.DashboardService] - Started dashboard at https://***.***.***.***:8443
22:23:06.454 [INFO ] [openhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
22:23:06.455 [INFO ] [rt.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'broker'
22:23:07.149 [INFO ] [marthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
22:23:18.393 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (BRIDGE_OFFLINE) to UNINITIALIZED
22:23:18.401 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
22:23:18.403 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:station:1350lon000474' changed from OFFLINE (COMMUNICATION_ERROR): Errorcode: 0 to UNINITIALIZED
22:23:18.408 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:station:1350lon000474' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
22:23:18.598 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
22:23:18.606 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:station:1350lon000474' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
22:23:19.035 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:station:1350lon000474' changed from INITIALIZING to ONLINE
22:23:19.054 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
22:23:19.058 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from INITIALIZING to ONLINE
22:24:32.324 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928275","total":0},"success":true}
22:24:33.334 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928276","total":0},"success":true}
22:24:34.370 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928277","total":0},"success":true}
22:24:35.338 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928278","total":0},"success":true}
22:24:36.365 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928279","total":0},"success":true}
22:24:37.380 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928280","total":0},"success":true}
22:24:38.311 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928281","total":0},"success":true}
22:24:39.294 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928282","total":0},"success":true}
22:24:40.416 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928283","total":0},"success":true}
22:24:41.345 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928284","total":0},"success":true}
22:24:42.321 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928285","total":0},"success":true}
22:24:43.315 [INFO ] [smarthome.event.ItemStateChangedEvent] - CAM_Roof_Event_EventDetected changed from OFF to ON
22:24:50.060 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Thread Event
22:24:50.357 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Thread Event to ONLINE
22:25:14.059 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Thread Event
22:25:14.368 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Thread Event to ONLINE
22:25:38.059 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Thread Event
22:25:38.304 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Thread Event to ONLINE
22:25:48.285 [INFO ] [smarthome.event.ItemStateChangedEvent] - CAM_Roof_Event_EventDetected changed from ON to OFF
22:25:49.346 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928352","total":0},"success":true}
[...]
22:26:40.404 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928403","total":0},"success":true}
22:26:40.922 [INFO ] [smarthome.event.ItemStateChangedEvent] - SamsungTV_Channel changed from 6 to 1
22:26:41.326 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928404","total":0},"success":true}
[...]
22:26:49.513 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928412","total":0},"success":true}
22:26:49.769 [INFO ] [smarthome.event.ItemStateChangedEvent] - SamsungTV_Channel changed from 1 to 3
22:26:50.288 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928413","total":0},"success":true}
[...]
22:29:11.332 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928554","total":0},"success":true}
22:29:12.579 [INFO ] [smarthome.event.ItemStateChangedEvent] - CAM_Roof_Event_EventDetected changed from OFF to ON
22:29:29.059 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Thread Event
22:29:29.419 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Thread Event to ONLINE
22:30:16.365 [INFO ] [smarthome.event.ItemStateChangedEvent] - CAM_Roof_Event_EventDetected changed from ON to OFF
22:30:17.344 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928620","total":0},"success":true}
[...]
22:30:59.324 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928662","total":0},"success":true}
22:31:01.059 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Thread Event
22:31:01.864 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928665","total":0},"success":true}
22:31:01.866 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Thread Event to ONLINE
22:31:02.332 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928665","total":0},"success":true}
[...]
22:31:34.332 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928697","total":0},"success":true}
22:31:36.059 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Thread Event
22:31:36.389 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928699","total":0},"success":true}
22:31:36.391 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Thread Event to ONLINE
22:31:37.357 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928700","total":0},"success":true}
[...]
22:32:04.289 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928727","total":0},"success":true}
22:32:06.059 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Thread Event
22:32:06.652 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928729","total":0},"success":true}
22:32:06.654 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Thread Event to ONLINE
22:32:08.060 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Thread Event
22:32:08.424 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928731","total":0},"success":true}
22:32:08.425 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Thread Event to ONLINE
22:32:09.344 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928732","total":0},"success":true}
[...]
22:32:55.323 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928778","total":0},"success":true}
22:32:57.059 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Thread Event
22:32:57.302 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928780","total":0},"success":true}
22:32:57.304 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Thread Event to ONLINE
22:32:58.328 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928781","total":0},"success":true}
[...]
22:33:17.300 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928800","total":0},"success":true}
22:33:19.059 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Thread Event
22:33:19.390 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928802","total":0},"success":true}
22:33:19.392 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Thread Event to ONLINE
22:33:20.397 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928803","total":0},"success":true}
[...]
22:33:33.304 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928816","total":0},"success":true}
22:33:35.059 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Thread Event
22:33:35.506 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928818","total":0},"success":true}
22:33:35.509 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Thread Event to ONLINE
22:33:36.355 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514928819","total":0},"success":true}
[...]
22:39:55.345 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514929198","total":0},"success":true}
22:39:57.059 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Thread Event
22:39:57.713 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514929201","total":0},"success":true}
22:39:57.715 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Thread Event to ONLINE
22:39:58.329 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514929201","total":0},"success":true}
[...]
22:40:41.361 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514929244","total":0},"success":true}
22:40:43.059 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Thread Event
22:40:43.802 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514929247","total":0},"success":true}
22:40:43.803 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'synologysurveillancestation:camera:1350lon000474:14' changed from OFFLINE (COMMUNICATION_ERROR): Thread Event to ONLINE
22:40:44.268 [DEBUG] [nternal.webapi.request.SynoApiRequest] - RESPONSE: {"data":{"events":[],"offset":0,"timestamp":"1514929247","total":0},"success":true}
[...]

Regards, Danny

Pavion commented 6 years ago

Most of requests seems to come through with but few throwing an exception. Could you confirm that the overall functionality is still given?

I think I've found the problem: connection timeout. Either your network or your hardware are a bit slow and some requests just take too long.

I've increased the connection timeouts from now 1 to 3 seconds and made a new version. Just overwrite the old one.

org.openhab.binding.synologysurveillancestation-2.2.0-SNAPSHOT.zip

Danny89530 commented 6 years ago

Hi @Pavion, seems the last update has solved the issue, after overwriting the file 30 mins ago, no even _COMMUNICATIONERROR problem was found. I don't think is an hardware gap problem, the CPU use is at 0.1%, the memory is at 53% (remember that is a VM).

CPU/Mem Top:

top - 23:36:48 up 2 days, 12:25,  3 users,  **load average: 0,31, 0,14, 0,04**
Tasks: 118 total,   1 running, 117 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0,3 us,  0,1 sy,  0,0 ni, 99,6 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st
**KiB Mem:   2060896 total,  1113656 used**,   947240 free,   130772 buffers
KiB Swap:   392188 total,        0 used,   392188 free,   428292 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND
 7139 openhab   20   0 2530m 434m  16m S   1,3 21,6   2:46.14 java

IFTop stats:

TX:             cum:    135kB   peak:   49,4kb                         rates:   44,2kb  41,8kb  41,5kb
RX:                     126kB           55,3kb                                  36,0kb  37,1kb  38,8kb
TOTAL:                  261kB            104kb                                  80,2kb  78,8kb  80,4kb

Thanks for your pacience Let me know if I can do anything else :) Kindly regards, Danny

Pavion commented 6 years ago

Thank you for your patience! Seemingly most exceptions came from connection timeout. With your help I might just have fixed three issues :) What you can do?! Ideas, feedback, issues please!