Long delay in item state changing

Running build 1356. System has been up for 8 days. Hardware is core i5 at 4.2 GHz.

Anyone have an idea why it would take 20+ seconds for the item state to be updated?

2018-09-18 13:36:43.103 [ome.event.ItemCommandEvent] - Item 'Kitchen_RecessedMain' received command OFF
2018-09-18 13:36:43.104 [nt.ItemStatePredictedEvent] - Kitchen_RecessedMain predicted to become OFF


2018-09-18 13:37:04.799 [vent.ItemStateChangedEvent] - Kitchen_RecessedMain changed from 100 to 0

Ok, this seems to be related to the zwave binding.


I have the command repoll configured fo 1500 ms, but instead it is happening in 21600 ms. I’m not sure why, and I can’t figure out where the 21600 ms is coming from.

Edit: My pollling period is set to 6 hours.

I see at least one issue, although I’m not sure if this is the cause. In the code below, the config parameter is placed in repollParm, however, inside the if statement pollParm is used.

You need to understand what is happening…

The repoll delay is a delay after “sending” the command before “sending” the poll. Note that “sending” really means “adding to the queue”. So, if there are other things happening, then the poll will be sent much later - polling is designed to be one of the lowest priority traffic.

You are right that the initialisation looks wrong, but it seems unlikely that this is the cause of your issue since then it wouldn’t be 20ish seconds, it would be 6 hours.

Can you provide the log showing this issue? Is it always exactly the same or is it variable?

I understand. But I don’t think there’s much else happening. I’m looking more closely at the logs now, so I’ll provide more info shortly.

Yeah, that’s what I thought too.

I’ll capture a full debug log shortly.

So far it appears to be the same (at least for this node).

Hmm. This is weird. HABmin shows 6 hours for the poll period.

But the jsondb shows this. That certainly explains where the 21600 is coming from.

      "configuration": {
        "properties": {
          "action_heal": false,
          "switchall_mode": 255,
          "binding_cmdrepollperiod": 1500,
          "action_reinit": false,
          "nodename_name": "KitchenMain",
          "nodename_location": "",
          "action_failed": false,
          "group_1": [
          "action_remove": false,
          "binding_pollperiod": 21600,
          "node_id": 40

Ok, that makes sense then. I’ll update this.

For reference -:

So the poll period is stored in seconds (21,600 seconds is 6 hours). And the command repoll period is stored in msec (e.g. 1500). I think that explains everything I was seeing.

Thanks for the quick fix. :clap:

Now if we can just get cloudbees working again… :roll_eyes:


Yep - it’s been completely hosed for the past 13 hours (or more)…

Thanks for kicking off the build!

I haven’t (yet) - I’m just making sure that the last PR I created earlier builds correctly before I merge it, then I’ll kick off the main rebuild…