Getting Persistence service to work with refresh rule

Hi
Need some guidance and advices here guys.

Running Openhabian 1.4 with openhab v2.2.0 on a RPi3 with a Razberry2 Z-wave serial card
Have installed the experimental Z-Wave Binding and finally got this to work with my Z-wave nodes including my DanaLockv3 doorlock
Im no expert on writing scripts and code so i decided to test out the Experimental Rule Engine. This works great with my Philips Hue lights and ive also managed to control my doorlock with a rule made with the Rule Engine.

{
  "884f11e6-8c0a-42ad-b837-5f409a151598": {
    "class": "org.eclipse.smarthome.automation.Rule",
    "value": {
      "triggers": [
        {
          "id": "1",
          "label": "it is a fixed time of day",
          "description": "Triggers at a specified time",
          "configuration": {
            "properties": {
              "time": "06:55"
            }
          },
          "type": "timer.TimeOfDayTrigger"
        }
      ],
      "conditions": [
        {
          "id": "3",
          "label": "an item has a given state",
          "description": "Compares the item state with the given value",
          "configuration": {
            "properties": {
              "itemName": "Node6_DoorLock",
              "operator": "\u003d",
              "state": "OFF"
            }
          },
          "type": "core.ItemStateCondition"
        }
      ],
      "actions": [
        {
          "id": "2",
          "label": "send a command",
          "description": "Sends a command to a specified item.",
          "configuration": {
            "properties": {
              "itemName": "Node6_DoorLock",
              "command": "ON"
            }
          },
          "type": "core.ItemCommandAction"
        }
      ],
      "configuration": {
        "properties": {}
      },
      "configDescriptions": [],
      "uid": "884f11e6-8c0a-42ad-b837-5f409a151598",
      "name": "DanaLockRule",
      "tags": [],
      "visibility": "VISIBLE",
      "description": "LockFrontDoor"
    }
  }
}

This worked like a charm. All until i rebooted the RPiā€¦
Now my ā€œDanaLockRuleā€ show up as UNINITILIZED in the PaperUI. If i disable and then enable the rule it goes into IDLE mode and gets executed at the specified time.
Here is part of the event.log after reboot:

2017-12-25 07:44:19.441 [.ItemChannelLinkAddedEvent] - Link 'Node6_DoorLock-zwave:device:7fb42261:node6:lock_door' has been added.
2017-12-25 07:44:19.443 [.ItemChannelLinkAddedEvent] - Link 'Lysfarge_Trapp-hue:0210:00178869615d:3:color' has been added.
2017-12-25 07:44:19.444 [.ItemChannelLinkAddedEvent] - Link 'Lysfarge_Trapp-hue:0210:00178869615d:2:color' has been added.
2017-12-25 07:44:19.446 [.ItemChannelLinkAddedEvent] - Link 'MaximusPC1000120_Online-network:pingdevice:10_0_0_120:online' has been added.
2017-12-25 07:44:19.704 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_120' changed from UNINITIALIZED to INITIALIZING
2017-12-25 07:44:19.871 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_120' changed from INITIALIZING to ONLINE
2017-12-25 07:44:19.963 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_120' has been updated.
2017-12-25 07:44:19.970 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_50' changed from UNINITIALIZED to INITIALIZING
2017-12-25 07:44:20.027 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_50' changed from INITIALIZING to ONLINE
2017-12-25 07:44:20.164 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_50' has been updated.
2017-12-25 07:44:20.180 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_110' changed from UNINITIALIZED to INITIALIZING
2017-12-25 07:44:20.201 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_120' has been updated.
2017-12-25 07:44:20.257 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_110' changed from INITIALIZING to ONLINE
2017-12-25 07:44:20.308 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_110' has been updated.
2017-12-25 07:44:20.340 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_138' changed from UNINITIALIZED to INITIALIZING
2017-12-25 07:44:20.356 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_110' has been updated.
2017-12-25 07:44:20.390 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_138' changed from INITIALIZING to ONLINE
2017-12-25 07:44:20.450 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_138' has been updated.
2017-12-25 07:44:20.481 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_138' has been updated.
2017-12-25 07:44:20.638 [vent.ItemStateChangedEvent] - SamsungXcover41000110_Online changed from NULL to ON
2017-12-25 07:44:20.641 [vent.ItemStateChangedEvent] - SamsungXcover41000110_LatencyMs changed from NULL to 30.0
2017-12-25 07:44:20.644 [vent.ItemStateChangedEvent] - SamsungXcover41000110_LastSeen changed from NULL to 2017-12-25T07:44:20.281+0100
2017-12-25 07:44:20.648 [vent.ItemStateChangedEvent] - MaximusPC1000120_Online changed from NULL to ON
2017-12-25 07:44:22.628 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_50' has been updated.
2017-12-25 07:44:25.309 [thome.event.RuleAddedEvent] - Rule '884f11e6-8c0a-42ad-b837-5f409a151598' has been added.
2017-12-25 07:44:25.326 [.event.RuleStatusInfoEvent] - 884f11e6-8c0a-42ad-b837-5f409a151598 updated: INITIALIZING
2017-12-25 07:44:25.334 [.event.RuleStatusInfoEvent] - 884f11e6-8c0a-42ad-b837-5f409a151598 updated: UNINITIALIZED (CONFIGURATION_ERROR): Validation of rule 884f11e6-8c0a-42ad-b837-5f409a151598 has failed! Condition Type "core.ItemStateCondition" does not exist!
2017-12-25 07:44:25.947 [.event.RuleStatusInfoEvent] - 884f11e6-8c0a-42ad-b837-5f409a151598 updated: INITIALIZING
2017-12-25 07:44:25.962 [.event.RuleStatusInfoEvent] - 884f11e6-8c0a-42ad-b837-5f409a151598 updated: UNINITIALIZED (CONFIGURATION_ERROR): Validation of rule 884f11e6-8c0a-42ad-b837-5f409a151598 has failed! Condition Type "core.ItemStateCondition" does not exist!
2017-12-25 07:44:26.815 [vent.ItemStateChangedEvent] - Node6_DoorLock changed from NULL to ON
2017-12-25 07:44:27.152 [hingStatusInfoChangedEvent] - 'hue:bridge:00178869615d' changed from UNINITIALIZED to INITIALIZING
2017-12-25 07:44:27.211 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:3' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-12-25 07:44:27.244 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:2' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-12-25 07:44:27.248 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:1' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-12-25 07:44:27.250 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:4' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-12-25 07:44:30.668 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:7fb42261' changed from UNINITIALIZED to INITIALIZING
2017-12-25 07:44:30.722 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:7fb42261' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2017-12-25 07:44:30.792 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from UNINITIALIZED to INITIALIZING
2017-12-25 07:44:30.825 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2017-12-25 07:44:30.853 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from UNINITIALIZED to INITIALIZING
2017-12-25 07:44:30.855 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2017-12-25 07:44:37.798 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:7fb42261' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2017-12-25 07:44:37.803 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2017-12-25 07:44:37.809 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2017-12-25 07:44:37.857 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from ONLINE to ONLINE: Node initialising: INIT_NEIGHBORS
2017-12-25 07:44:37.917 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from ONLINE to ONLINE: Node initialising: INIT_NEIGHBORS
2017-12-25 07:44:37.979 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from ONLINE: Node initialising: INIT_NEIGHBORS to ONLINE: Node initialising: FAILED_CHECK
2017-12-25 07:44:38.035 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from ONLINE: Node initialising: INIT_NEIGHBORS to ONLINE: Node initialising: FAILED_CHECK
2017-12-25 07:44:38.099 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from ONLINE: Node initialising: FAILED_CHECK to ONLINE: Node initialising: REQUEST_NIF
2017-12-25 07:44:38.151 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from ONLINE: Node initialising: FAILED_CHECK to ONLINE: Node initialising: REQUEST_NIF
2017-12-25 07:44:38.426 [hingStatusInfoChangedEvent] - 'hue:bridge:00178869615d' changed from INITIALIZING to ONLINE
2017-12-25 07:44:38.440 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:3' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-12-25 07:44:38.458 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:2' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-12-25 07:44:38.460 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:4' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-12-25 07:44:38.477 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:3' changed from INITIALIZING to ONLINE
2017-12-25 07:44:38.527 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:2' changed from INITIALIZING to ONLINE
2017-12-25 07:44:38.542 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:1' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-12-25 07:44:38.545 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:4' changed from INITIALIZING to ONLINE
2017-12-25 07:44:38.578 [vent.ItemStateChangedEvent] - Lysfarge_Trapp changed from NULL to 326,100,27
2017-12-25 07:44:38.597 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:1' changed from INITIALIZING to ONLINE
2017-12-25 07:44:38.610 [vent.ItemStateChangedEvent] - Lysstyrke_Trapp changed from NULL to 86
2017-12-25 07:44:39.709 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2017-12-25 07:44:39.842 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
#removed some unrelated stuff
2017-12-25 07:49:23.082 [INFO ] [mmandclass.ZWaveDoorLockCommandClass] - NODE 6: Door-Lock config report - timeoutEnabled=false timeoutMinutes=254, timeoutSeconds=254

I have also tried to use the MapDB Persistence service. This is configured like this:

Strategies {
        default = everyUpdate
}

Items {
        // persist all items on every change and restore them from the db at startup
        gRestoreOnStartup* : strategy = everyChange, restoreOnStartup
}

Following advices given in this post: Automation/Orchestration Design Patterns

I have also read about the use of Persistence
and tried to follow the sugested workaround nr.2 in the Startup Behavior section but i cannot get this solution to work in openhabian. I think this can be related to the fact that the openhabian directories has a different structure than the OpenHab.
I find it very very confusing that the Samba shared folders is renamed and not corresponding with the actual directory names. I wasted quite some time figuring this out and i still couldnā€™t make the refresh.rules run the rules_refresh.sh script . The Samba share folder is named: \OPENHABIANPI\openHAB-share\openhab2-conf but to access this in the PuTTy console the directory is revealed to be: /etc/openhab2/ ā€¦ Stupid little things like this can totally break the spirit of a newbie at the very start of his/hers endeavours in the OpenHab environment.

Im starting to think that going for the openhabian setup maybe was a wrong move. Will Openhab on a Raspbian system be easier to work with given that there is better documentation and that the majority of users have their experience on OpenHab? But im pretty sure ill have to deal with this exact same problem with my Door Lock ruleā€¦ Arg !!!
Anyone sees whats goes wrong with my Persistence service? Seems like it wont work without applying a delayed rule initialization.

Edit: added part of the openhab.log in case this is needed:

2017-12-25 07:44:15.101 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2017-12-25 07:44:18.072 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2017-12-25 07:44:19.865 [WARN ] [lipse.smarthome.io.net.exec.ExecUtil] - Execution failed (Exit value: -559038737. Caused by java.io.IOException: Cannot run program "arping" (in directory "."): error=2, Ingen slik fil eller filkatalog)
2017-12-25 07:44:19.893 [INFO ] [ternal.dhcp.DHCPPacketListenerServer] - DHCP request packet listener online
2017-12-25 07:44:20.020 [WARN ] [lipse.smarthome.io.net.exec.ExecUtil] - Execution failed (Exit value: -559038737. Caused by java.io.IOException: Cannot run program "arping" (in directory "."): error=2, Ingen slik fil eller filkatalog)
2017-12-25 07:44:20.245 [WARN ] [lipse.smarthome.io.net.exec.ExecUtil] - Execution failed (Exit value: -559038737. Caused by java.io.IOException: Cannot run program "arping" (in directory "."): error=2, Ingen slik fil eller filkatalog)
2017-12-25 07:44:20.381 [WARN ] [lipse.smarthome.io.net.exec.ExecUtil] - Execution failed (Exit value: -559038737. Caused by java.io.IOException: Cannot run program "arping" (in directory "."): error=2, Ingen slik fil eller filkatalog)
2017-12-25 07:44:23.689 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-12-25 07:44:24.177 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2017-12-25 07:44:24.270 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-12-25 07:44:24.401 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-12-25 07:44:24.591 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-12-25 07:44:30.726 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyAMA0'
2017-12-25 07:44:30.845 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2017-12-25 07:44:30.896 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2017-12-25 07:44:30.899 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2017-12-25 07:44:34.441 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-12-25 07:44:34.444 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 3: Node found
2017-12-25 07:44:34.446 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 6: Node found
2017-12-25 07:44:34.449 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-12-25 07:44:34.451 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-12-25 07:44:34.454 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-12-25 07:44:34.456 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 3
2017-12-25 07:44:34.458 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-12-25 07:49:23.082 [INFO ] [mmandclass.ZWaveDoorLockCommandClass] - NODE 6: Door-Lock config report - timeoutEnabled=false timeoutMinutes=254, timeoutSeconds=254

Trying to solve why the ā€œWorkaround 2ā€ option (look in post above for reference) wonā€™t workā€¦
Here is what i get when testrunning the script in the console (PuTTy):


[17:16:09] openhabian@openHABianPi:/etc/openhab2$ cd /etc/openhab2
[17:16:33] openhabian@openHABianPi:/etc/openhab2$ rules_refresh.sh
-bash: rules_refresh.sh: command not found
[17:18:27] openhabian@openHABianPi:/etc/openhab2$ bash -n rules_refresh.sh      [17:27:07] openhabian@openHABianPi:/etc/openhab2$ bash -x rules_refresh.sh
+ sleep 5
+ cd '[full_path_to_openhab]' /etc/openhab2/rules/
rules_refresh.sh: line 3: cd: too many arguments
++ find '*.rules'
++ grep -v refresh.rules
find: ā€˜*.rulesā€™: No such file or directory
+ RULES=

I think by solving this the item condition will no longer cause the initialization error returning this following statement:

"core.ItemStateCondition" does not exist!

What seems to be the problem is that the itemstate is reported to be NULL instead of the correct two options ON / OFF

as ./ is not in the search path for commands, you have to use ./rules_refresh.sh as command
Please ensure that rules_refresh.sh is marked as executable.

Ok. Now im a bit confused on what you are trying to tell me. I clearly cannot use the suggested code from this doc: Startup Behavior
So ive tried first changing the 3rd line in openhab2/rules/refresh.rules file:

executeCommandLine("./configurations/rules_refresh.sh") # to this:
executeCommandLine("./openhab2/rules_refresh.sh")

and at the same time corrected the 3rd line in openhab2/rules_refresh.sh file:

cd [full_path_to_openhab]/configurations/rules/ # to this:
cd [full_path_to_openhab] /etc/openhab2/rules/

And yes the file is made executable.
That did not work for me as you can see from the ā€œbash -n rules_refresh.shā€ in my post 2 above.
It clearly states line 3: cd: too many arguments
Should i remove this? : '[full_path_to_openhab]'
And finally it starts to dawn on me that nothing of this will fix the original problem since the Experimental Rule Engine saves the rules in the \OPENHABIANPI\openHAB-share\openhab2-userdata\jsondb and not in the /etc/openhab2/rules/ directory

Can i rewrite this script to address the jsondb rule files?

Update:
Fixed unrelated problem with missing ā€œarpingā€ utility. It caused this WARN :

[lipse.smarthome.io.net.exec.ExecUtil] - Execution failed (Exit value: -559038737. Caused by java.io.IOException: Cannot run program "arping" (in directory "."): error=2, No such file or directory)

This is fixed by installing the missing utility in console: sudo apt install arping
The problem involving the refresh.rules module and the rules_refresh.sh script was solved by changing the text inside the files like this:
The file refresh.rules must be located in etc/openhab2/rules/ (this is the same as the \OPENHABIANPI\openHAB-share\openhab2-conf share folder)

var boolean reloadOnce = true
rule "Refresh rules after persistence service started"
  when System started
then
  if(reloadOnce)
    executeCommandLine(" /etc/openhab2/rules_refresh.sh")
  else
    println("reloadOnce is false")
  reloadOnce = false
end

The file rules_refresh.sh must be located in etc/openhab2 (this is the same as the \OPENHABIANPI\openHAB-share\openhab2-conf share folder)

# This script is called by openHAB after the persistence service has started
sleep 5
cd /etc/openhab2/rules/
RULES=`find *.rules | grep -v refresh.rules`
for f in $RULES
do
  touch $f
done 

Here is the openhab.log and the event.log (showing only latest restart)

2017-12-25 23:20:15.077 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2017-12-25 23:20:28.944 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2017-12-25 23:20:29.301 [INFO ] [io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection
2017-12-25 23:20:29.327 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = 6c6e9a3a-7636-4ea1-b775-0b62e0a26609, base URL = http://localhost:8080)
2017-12-25 23:20:29.533 [INFO ] [assic.internal.servlet.WebAppServlet] - Stopped Classic UI
2017-12-25 23:20:29.582 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet
2017-12-25 23:20:30.247 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2017-12-25 23:20:30.279 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2017-12-25 23:20:30.304 [INFO ] [.dashboard.internal.DashboardService] - Stopped dashboard
2017-12-25 23:21:02.921 [INFO ] [.internal.GenericScriptEngineFactory] - Activated scripting support for ECMAScript
2017-12-25 23:21:04.765 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to no_NO, Location set to null, Time zone set to Europe/Oslo
2017-12-25 23:21:06.741 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://10.0.0.100:8080
2017-12-25 23:21:06.745 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://10.0.0.100:8443
2017-12-25 23:21:07.301 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 6c6e9a3a-7636-4ea1-b775-0b62e0a26609, base URL = http://localhost:8080)
2017-12-25 23:21:15.241 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2017-12-25 23:21:18.465 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2017-12-25 23:21:20.910 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'refresh.rules'
2017-12-25 23:21:22.515 [INFO ] [ternal.dhcp.DHCPPacketListenerServer] - DHCP request packet listener online
2017-12-25 23:21:26.198 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-12-25 23:21:26.672 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2017-12-25 23:21:26.753 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-12-25 23:21:26.892 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-12-25 23:21:27.083 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-12-25 23:21:31.120 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine ' /etc/openhab2/rules_refresh.sh'
2017-12-25 23:21:33.918 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyAMA0'
2017-12-25 23:21:34.081 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2017-12-25 23:21:34.123 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2017-12-25 23:21:34.126 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2017-12-25 23:21:37.683 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-12-25 23:21:37.687 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 3: Node found
2017-12-25 23:21:37.690 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 6: Node found
2017-12-25 23:21:37.692 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-12-25 23:21:37.694 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-12-25 23:21:37.697 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-12-25 23:21:37.700 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 3
2017-12-25 23:21:37.701 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-12-25 23:27:09.482 [INFO ] [mmandclass.ZWaveDoorLockCommandClass] - NODE 6: Door-Lock config report - timeoutEnabled=false timeoutMinutes=254, timeoutSeconds=254

2017-12-25 23:20:25.603 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from ONLINE to UNINITIALIZED
2017-12-25 23:20:25.761 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-12-25 23:20:25.764 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from ONLINE to UNINITIALIZED
2017-12-25 23:20:25.845 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-12-25 23:20:25.848 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:7fb42261' changed from ONLINE to UNINITIALIZED
2017-12-25 23:20:28.964 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:7fb42261' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-12-25 23:20:29.017 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_138' changed from ONLINE to UNINITIALIZED
2017-12-25 23:20:29.026 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_138' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-12-25 23:20:29.033 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_110' changed from ONLINE to UNINITIALIZED
2017-12-25 23:20:29.036 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_110' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-12-25 23:20:29.040 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_120' changed from ONLINE to UNINITIALIZED
2017-12-25 23:20:29.047 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_120' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-12-25 23:20:29.052 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_50' changed from ONLINE to UNINITIALIZED
2017-12-25 23:20:29.053 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_50' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-12-25 23:20:29.076 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:1' changed from ONLINE to UNINITIALIZED
2017-12-25 23:20:29.080 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:1' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-12-25 23:20:29.082 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:3' changed from ONLINE to UNINITIALIZED
2017-12-25 23:20:29.093 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:3' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-12-25 23:20:29.095 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:2' changed from ONLINE to UNINITIALIZED
2017-12-25 23:20:29.103 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:2' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-12-25 23:20:29.107 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:4' changed from ONLINE to UNINITIALIZED
2017-12-25 23:20:29.115 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:4' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-12-25 23:20:29.116 [hingStatusInfoChangedEvent] - 'hue:bridge:00178869615d' changed from ONLINE to UNINITIALIZED
2017-12-25 23:20:29.128 [hingStatusInfoChangedEvent] - 'hue:bridge:00178869615d' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-12-25 23:20:29.809 [temChannelLinkRemovedEvent] - Link 'Lysfarge_Trapp => hue:0210:00178869615d:4:color' has been removed.
2017-12-25 23:20:29.811 [temChannelLinkRemovedEvent] - Link 'Lysstyrke_Trapp => hue:0210:00178869615d:3:color_temperature' has been removed.
2017-12-25 23:20:29.813 [temChannelLinkRemovedEvent] - Link 'Lysfarge_Trapp => hue:0210:00178869615d:1:color' has been removed.
2017-12-25 23:20:29.814 [temChannelLinkRemovedEvent] - Link 'SamsungXcover41000110_Online => network:pingdevice:10_0_0_110:online' has been removed.
2017-12-25 23:20:29.817 [temChannelLinkRemovedEvent] - Link 'SamsungXcover41000110_LastSeen => network:pingdevice:10_0_0_110:lastseen' has been removed.
2017-12-25 23:20:29.819 [temChannelLinkRemovedEvent] - Link 'Lysstyrke_Trapp => hue:0210:00178869615d:1:color_temperature' has been removed.
2017-12-25 23:20:29.823 [temChannelLinkRemovedEvent] - Link 'Lysstyrke_Trapp => hue:0210:00178869615d:4:color_temperature' has been removed.
2017-12-25 23:20:29.827 [temChannelLinkRemovedEvent] - Link 'Lysstyrke_Trapp => hue:0210:00178869615d:2:color_temperature' has been removed.
2017-12-25 23:20:29.829 [temChannelLinkRemovedEvent] - Link 'SamsungXcover41000110_LatencyMs => network:pingdevice:10_0_0_110:latency' has been removed.
2017-12-25 23:20:29.832 [temChannelLinkRemovedEvent] - Link 'Node6_DoorLock => zwave:device:7fb42261:node6:lock_door' has been removed.
2017-12-25 23:20:29.833 [temChannelLinkRemovedEvent] - Link 'Lysfarge_Trapp => hue:0210:00178869615d:3:color' has been removed.
2017-12-25 23:20:29.834 [temChannelLinkRemovedEvent] - Link 'Lysfarge_Trapp => hue:0210:00178869615d:2:color' has been removed.
2017-12-25 23:20:29.836 [temChannelLinkRemovedEvent] - Link 'MaximusPC1000120_Online => network:pingdevice:10_0_0_120:online' has been removed.
2017-12-25 23:20:29.946 [ome.event.RuleRemovedEvent] - Rule '884f11e6-8c0a-42ad-b837-5f409a151598' has been removed.
2017-12-25 23:21:21.974 [.ItemChannelLinkAddedEvent] - Link 'Lysfarge_Trapp-hue:0210:00178869615d:4:color' has been added.
2017-12-25 23:21:21.981 [.ItemChannelLinkAddedEvent] - Link 'Lysstyrke_Trapp-hue:0210:00178869615d:3:color_temperature' has been added.
2017-12-25 23:21:21.986 [.ItemChannelLinkAddedEvent] - Link 'Lysfarge_Trapp-hue:0210:00178869615d:1:color' has been added.
2017-12-25 23:21:21.993 [.ItemChannelLinkAddedEvent] - Link 'SamsungXcover41000110_Online-network:pingdevice:10_0_0_110:online' has been added.
2017-12-25 23:21:21.995 [.ItemChannelLinkAddedEvent] - Link 'SamsungXcover41000110_LastSeen-network:pingdevice:10_0_0_110:lastseen' has been added.
2017-12-25 23:21:21.997 [.ItemChannelLinkAddedEvent] - Link 'Lysstyrke_Trapp-hue:0210:00178869615d:1:color_temperature' has been added.
2017-12-25 23:21:22.008 [.ItemChannelLinkAddedEvent] - Link 'Lysstyrke_Trapp-hue:0210:00178869615d:4:color_temperature' has been added.
2017-12-25 23:21:22.010 [.ItemChannelLinkAddedEvent] - Link 'Lysstyrke_Trapp-hue:0210:00178869615d:2:color_temperature' has been added.
2017-12-25 23:21:22.013 [.ItemChannelLinkAddedEvent] - Link 'SamsungXcover41000110_LatencyMs-network:pingdevice:10_0_0_110:latency' has been added.
2017-12-25 23:21:22.015 [.ItemChannelLinkAddedEvent] - Link 'Node6_DoorLock-zwave:device:7fb42261:node6:lock_door' has been added.
2017-12-25 23:21:22.018 [.ItemChannelLinkAddedEvent] - Link 'Lysfarge_Trapp-hue:0210:00178869615d:3:color' has been added.
2017-12-25 23:21:22.021 [.ItemChannelLinkAddedEvent] - Link 'Lysfarge_Trapp-hue:0210:00178869615d:2:color' has been added.
2017-12-25 23:21:22.025 [.ItemChannelLinkAddedEvent] - Link 'MaximusPC1000120_Online-network:pingdevice:10_0_0_120:online' has been added.
2017-12-25 23:21:22.371 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_120' changed from UNINITIALIZED to INITIALIZING
2017-12-25 23:21:22.505 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_120' changed from INITIALIZING to ONLINE
2017-12-25 23:21:22.550 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_120' has been updated.
2017-12-25 23:21:22.623 [vent.ItemStateChangedEvent] - MaximusPC1000120_Online changed from NULL to ON
2017-12-25 23:21:22.637 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_120' has been updated.
2017-12-25 23:21:22.655 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_50' changed from UNINITIALIZED to INITIALIZING
2017-12-25 23:21:22.732 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_50' changed from INITIALIZING to ONLINE
2017-12-25 23:21:22.761 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_50' has been updated.
2017-12-25 23:21:22.776 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_120' has been updated.
2017-12-25 23:21:23.519 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_50' has been updated.
2017-12-25 23:21:23.543 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_110' changed from UNINITIALIZED to INITIALIZING
2017-12-25 23:21:23.595 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_110' changed from INITIALIZING to ONLINE
2017-12-25 23:21:23.623 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_50' has been updated.
2017-12-25 23:21:23.635 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_110' has been updated.
2017-12-25 23:21:23.654 [vent.ItemStateChangedEvent] - SamsungXcover41000110_LastSeen changed from NULL to UNDEF
2017-12-25 23:21:23.678 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_138' changed from UNINITIALIZED to INITIALIZING
2017-12-25 23:21:23.726 [hingStatusInfoChangedEvent] - 'network:pingdevice:10_0_0_138' changed from INITIALIZING to ONLINE
2017-12-25 23:21:23.742 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_138' has been updated.
2017-12-25 23:21:23.758 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_138' has been updated.
2017-12-25 23:21:23.804 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_138' has been updated.
2017-12-25 23:21:27.828 [thome.event.RuleAddedEvent] - Rule '884f11e6-8c0a-42ad-b837-5f409a151598' has been added.
2017-12-25 23:21:27.845 [.event.RuleStatusInfoEvent] - 884f11e6-8c0a-42ad-b837-5f409a151598 updated: INITIALIZING
2017-12-25 23:21:27.853 [.event.RuleStatusInfoEvent] - 884f11e6-8c0a-42ad-b837-5f409a151598 updated: UNINITIALIZED (CONFIGURATION_ERROR): Validation of rule 884f11e6-8c0a-42ad-b837-5f409a151598 has failed! Condition Type "core.ItemStateCondition" does not exist!
2017-12-25 23:21:28.518 [.event.RuleStatusInfoEvent] - 884f11e6-8c0a-42ad-b837-5f409a151598 updated: INITIALIZING
2017-12-25 23:21:28.522 [.event.RuleStatusInfoEvent] - 884f11e6-8c0a-42ad-b837-5f409a151598 updated: UNINITIALIZED (CONFIGURATION_ERROR): Validation of rule 884f11e6-8c0a-42ad-b837-5f409a151598 has failed! Condition Type "core.ItemStateCondition" does not exist!
2017-12-25 23:21:28.627 [vent.ItemStateChangedEvent] - SamsungXcover41000110_Online changed from NULL to OFF
2017-12-25 23:21:28.641 [vent.ItemStateChangedEvent] - SamsungXcover41000110_LatencyMs changed from NULL to -1.0
2017-12-25 23:21:28.651 [vent.ItemStateChangedEvent] - SamsungXcover41000110_LatencyMs changed from -1.0 to UNDEF
2017-12-25 23:21:29.410 [vent.ItemStateChangedEvent] - Node6_DoorLock changed from NULL to ON
2017-12-25 23:21:29.606 [hingStatusInfoChangedEvent] - 'hue:bridge:00178869615d' changed from UNINITIALIZED to INITIALIZING
2017-12-25 23:21:29.644 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:3' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-12-25 23:21:29.649 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:2' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-12-25 23:21:29.654 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:1' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-12-25 23:21:29.663 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:4' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-12-25 23:21:33.883 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:7fb42261' changed from UNINITIALIZED to INITIALIZING
2017-12-25 23:21:33.914 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:7fb42261' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2017-12-25 23:21:34.034 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from UNINITIALIZED to INITIALIZING
2017-12-25 23:21:34.053 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from UNINITIALIZED to INITIALIZING
2017-12-25 23:21:34.071 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2017-12-25 23:21:34.075 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2017-12-25 23:21:40.679 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:7fb42261' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2017-12-25 23:21:40.695 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2017-12-25 23:21:40.703 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2017-12-25 23:21:40.745 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from ONLINE to ONLINE: Node initialising: INIT_NEIGHBORS
2017-12-25 23:21:40.797 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from ONLINE to ONLINE: Node initialising: INIT_NEIGHBORS
2017-12-25 23:21:40.815 [hingStatusInfoChangedEvent] - 'hue:bridge:00178869615d' changed from INITIALIZING to ONLINE
2017-12-25 23:21:40.838 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:2' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-12-25 23:21:40.841 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:3' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-12-25 23:21:40.854 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:1' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-12-25 23:21:40.857 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:4' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-12-25 23:21:40.893 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:2' changed from INITIALIZING to ONLINE
2017-12-25 23:21:40.931 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:3' changed from INITIALIZING to ONLINE
2017-12-25 23:21:40.967 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from ONLINE: Node initialising: INIT_NEIGHBORS to ONLINE: Node initialising: FAILED_CHECK
2017-12-25 23:21:40.972 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:1' changed from INITIALIZING to ONLINE
2017-12-25 23:21:40.978 [hingStatusInfoChangedEvent] - 'hue:0210:00178869615d:4' changed from INITIALIZING to ONLINE
2017-12-25 23:21:41.040 [vent.ItemStateChangedEvent] - Lysfarge_Trapp changed from NULL to 187,98,7
2017-12-25 23:21:41.060 [vent.ItemStateChangedEvent] - Lysstyrke_Trapp changed from NULL to 0
2017-12-25 23:21:41.066 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from ONLINE: Node initialising: INIT_NEIGHBORS to ONLINE: Node initialising: FAILED_CHECK
2017-12-25 23:21:41.070 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from ONLINE: Node initialising: FAILED_CHECK to ONLINE: Node initialising: REQUEST_NIF
2017-12-25 23:21:41.116 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from ONLINE: Node initialising: FAILED_CHECK to ONLINE: Node initialising: REQUEST_NIF
2017-12-25 23:21:41.245 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node3' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2017-12-25 23:21:42.863 [hingStatusInfoChangedEvent] - 'zwave:device:7fb42261:node6' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2017-12-25 23:21:49.623 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:7fb42261:node3' has been updated.
2017-12-25 23:21:49.664 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2017-12-25 23:21:49.745 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@18a0ae5
2017-12-25 23:27:03.717 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@3571f9
2017-12-25 23:27:03.736 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:7fb42261:node3' has been updated.
2017-12-25 23:27:08.183 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:7fb42261:node6' has been updated.
2017-12-25 23:27:08.201 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2017-12-25 23:27:09.496 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:7fb42261:node6' has been updated.
2017-12-25 23:27:09.498 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2017-12-25 23:27:10.198 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@15e0566
2017-12-25 23:27:29.678 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@7d8d89
2017-12-25 23:27:29.706 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:7fb42261:node6' has been updated.
2017-12-25 23:31:29.318 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_50' has been updated.
2017-12-25 23:32:29.417 [me.event.ThingUpdatedEvent] - Thing 'network:pingdevice:10_0_0_50' has been updated.

The original problem is not solved so i will continue my quest :slight_smile:

So to sum up:
MapDB Persistence is now up and running and i sorted out some other problems likely not related to the original problem.
I cannot find any solutions that will support the Experimental Rule engine so i think i will leave this for now and instead focus on writing my own rules which will be supported by the MapDB Persistence service.

Have i understood this correct?

Update: Have been working with text based ā€œ.rulesā€ for some weeks after realizing that this is the only way for now to implement more complex rules in my home automation system. As you can see from the previous post i figured out how to configure a script that refreshes all the rules in the rules directory after the persistences service is up and running after a restart of the OpenHab system. I assumed it was all good but studying the logs reveals that there have to be something still wrong with my setup. This is what the log shows after a restart:

2018-01-18 21:08:08.247 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'refresh.rules'

2018-01-18 21:08:13.441 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/etc/openhab2/rules_refresh.sh'

Nothing more happens (related to the refresh task)
If i however run the script from PuTTy: cd /etc/openhab2 (change working directory where the script is located)
Then run the script with: bash -x rules_refresh.sh
i get this feedback in the logs:

2018-01-18 21:24:28.965 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'DoorLock.rules'
2018-01-18 21:24:30.223 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'Presence.rules'

Im guessing this is a permission related issue. I dont know how to solve this without assistance. The script is as following:

# This script is called by openHAB after the persistence service has started
sleep 5
cd /etc/openhab2/rules/
RULES=`find *.rules | grep -v refresh.rules`
for f in $RULES
do
  touch $f
done 

Does the $f (force) even do anything in relation to the touch command (it does not seem to be)?

Start with How to solve Exec binding problems

Thanks for the tip. I found that i could test the script as user openhab (not as openhabian as i did in my recent post above) e.g.

[12:43:57] openhabian@openHABianPi:/etc/openhab2$ sudo -u openhab bash -x rules_refresh.sh

This runs the script as openhab and will report back like this:

+ sleep 5
+ cd /etc/openhab2/rules/
++ grep -v refresh.rules
++ find Adgangskontroll.rules Presence.rules refresh.rules
+ RULES='Adgangskontroll.rules
Presence.rules'
+ for f in $RULES
+ touch Adgangskontroll.rules
touch: cannot touch 'Adgangskontroll.rules': Permission denied
+ for f in $RULES
+ touch Presence.rules
touch: cannot touch 'Presence.rules': Permission denied

So missing permission is indeed what stops my script working. Updating this as my quest progresses.

Have been reading some more and try desperatly to extract some relevant information from the suggested post how to solve Exec binding problems
To be honest i find this ā€œtutorialā€ very confusing. Itā€™s not even clear to me how the Exec binding is relevant to my problem with the script not performing as expected. No places in this doc is the Exec binding even mentioned. The executeCommandLine have been executing my script even without the Exec binding installed so being introduced to this topic makes this issue i have really hard to solve. Im probably not experienced enough with OpenHab to understand what is suggested for meā€¦

Maybe itā€™s easier for me to understand if i get a few questions i have answered:

  1. Would i be better of installing openhab2 to a raspbian operating system because it seems to me that most tutorials and docs seems to cover openhabian installations very poorly?
  2. Is the ā€œWorkaround 2ā€ in the doc autdated and therfor not working as expected or is it the fact im on a sytem installed as openhabian that creates problems?
  1. As this is likely to be relevant for my problem what is the best way to solve this in my particular case?
    I clearly need to grant a specific user privileges to the all my .rules files but im not exactly sure if this is the openhabian or the openhab user (guess i can explore this with trial and error) and furthermore i will have to remember to to this change with all future .rules files i establish. I was wondering if there was a way to give this user the right permissions/privileges to the entire .rules directory?

Update: Just after posting this i remember the use of * (i do not what this symbol is called) and i gave it a try with following command:

[20:17:12] openhabian@openHABianPi:/etc/openhab2/rules$ sudo chown openhab *.rules

This is of course not an optimal solution because i still need to do this operation with every .rules file i create from now on but iā€™m pleased to inform you that the refresh of the .rules files is now working.

Iā€™ve only a couple of minutes,.

The point of the solving exec binding problems thread is to get the feedback from the script when running it to see why the script is not running as expected. You did this and found that the openhab user doesnā€™t have permissions on something the script needs to do.

Exec binding and executeCommandLine problems are almost always the same, permission or configuration problems on the openhab user. The thread gives a standardized way to find out what the problem is.

  1. openHABian IS OH installed to Raspbian. It just provides a set of scripts to setup and configure raspbian in the way you would probably do anyway were you doing everything by hand. Everything that is written about raspbian or even Linux in general also applies to openHABian. There is nothing special about openHABian in that regard. It is a standard OH install on Linux.

  2. To my knowledge those work arounds, correctly implemented, still work.

  3. It would be the openhab user. OH runs as the openhab user and therefore all scripts run from OH will run as the openhab user. The openhab user should already have the permissions on the .rules files so Iā€™m not sure why it is not allowed to touch the files. Are they owned by openhab:openhab? This is the default and expected permissions.

These files should ALWAYS be owned by openhab. You need to figure out why they are not. It can cause further problems if they are not owned by openhab. Are you editing files are the openhabian user directly on the RPi? That would explain it.

1 Like

It might be the fact that i used ā€œopenhabianā€ as login when i edited the .rules files on Notepad ++ on my pc (sambashare) ?

These files should ALWAYS be owned by openhab. You need to figure out why they are not. It can cause further problems if they are not owned by openhab. Are you editing files are the openhabian user directly on the RPi? That would explain it.

So log in and simply do a

sudo chown openhab:openhab /etc/openhab2/rules/*

hehe. That sounds like a solution yes! But you have to dumb it down a bit more so that i understand what this is doing.
This gives user openhab ā€œtotal jurisdictionā€ of all present and future files within the rules directory? :smile:

No, it simply changes the owner of all files in the folder /etc/openhab2/rules/. In fact, all the files in this folder should belong to this user anyway.

1 Like

Love it!
Can you confirm if the problem started with me entering the sambashared files as the user openhabian?

Iā€™m not sure about this, but itā€™s possible. I set my samba share to force all files to belong to user openhab and I never saw this happen.
my /etc/samba/smb.conf (just the part for the openhab-conf share):

[openhab_conf]
        valid users = openhab,@openhab
        write list = openhab,@openhab
        force user = openhab
        force group = openhab
        path = /etc/openhab2

Hmmm. Donā€™t seem to work on my setup. Allowed samba share users have to be configured in a different way in the ā€œopenhabian environmentā€ it seems like. I made the suggested change but when trying to open up the share as a different user (openhab) im rejected. Keep in mind the Samba share uses 3 different share folders on the openhabian system:
openHAB-conf
openhabian
openHAB-share
All 3 on network device called \OPENHABIANPI

I will try googling this topic but if someone have a suggestion how to solve this please chime in.
Btw. Im pretty sure this is a stock configuration set during installation of the openhabian and i cannot recall made any changes to user accounts. Seems like a problem that should be dealt with in future updates?

All samba shares are defined in smb.conf, openHABian does only the magic to automate the setup. As I donā€™t know whatā€™s the content of smb.conf in the openHABian environment, I can only guessā€¦

The content of the smb.conf should be very close to this
(i tried copy the text from the PuTTY terminal window but couldnā€™t figure out how to mark all the text to paste here into a code fence)