Smarthome: RulesJvmModelInferrer - Duplicate field

[martinvw]

After being busy setting everything up (via the Eclipse Smarthome Designer) I got a lot of warnings when saving:

2017-06-07 20:11:34.649 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Washing_Machine_Plug'. Ignoring 'org.eclipse.smarthome.core.library.items.SwitchItem'.
2017-06-07 20:11:34.649 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Washing_Machine_Plug_Power'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.649 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Washing_Machine_Plug_Energy'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.649 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Z_CV_Closet_Battery'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.649 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Z_CV_Closet_Temp'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.649 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Keuken_Buiten'. Ignoring 'org.eclipse.smarthome.core.library.items.SwitchItem'.
2017-06-07 20:11:34.649 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Coolcam_Plug_Energy_W'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.649 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Coolcam_Plug_Energy_V'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.649 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Coolcam_Plug_Energy_A'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.649 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Coolcam_Plug_Total_Energy'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.650 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Coolcam_Plug'. Ignoring 'org.eclipse.smarthome.core.library.items.SwitchItem'.
2017-06-07 20:11:34.650 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Coolcam_SIREN'. Ignoring 'org.eclipse.smarthome.core.library.items.SwitchItem'.
2017-06-07 20:11:34.650 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Coolcam_SIREN_battery'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.663 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Washing_Machine_Plug'. Ignoring 'org.eclipse.smarthome.core.library.items.SwitchItem'.
2017-06-07 20:11:34.663 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Washing_Machine_Plug_Power'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.663 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Washing_Machine_Plug_Energy'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.663 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Z_CV_Closet_Battery'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.663 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Z_CV_Closet_Temp'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.663 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Keuken_Buiten'. Ignoring 'org.eclipse.smarthome.core.library.items.SwitchItem'.
2017-06-07 20:11:34.663 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Coolcam_Plug_Energy_W'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.663 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Coolcam_Plug_Energy_V'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.663 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Coolcam_Plug_Energy_A'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.663 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Coolcam_Plug_Total_Energy'. Ignoring 'org.eclipse.smarthome.core.library.items.NumberItem'.
2017-06-07 20:11:34.663 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: 'Coolcam_Plug'. Ignoring 'org.eclipse.smarthome.core.library.items.SwitchItem'.

It seems I'm not the first and only one, see also

https://community.openhab.org/t/oh2b5-duplicate-field-item-name/19480
https://community.openhab.org/t/why-do-i-get-warn-duplicate-field-sonosplay-save/12108
https://community.openhab.org/t/astro-binding-duplicates/12384

And they all end in the closed issue https://github.com/eclipse/smarthome/issues/1574

I think that one should be either reopened or we should continue in this issue.

And of course I grepped whether I defined it double but I'm quite strict on defining all my items through files and only things through the paperUI. When grep-ing I get some hits in the json-db but I did not put them there...

[sjsf]

Thanks for reporting this. As you already opened this issue, let's continue here.

Could you please quickly check whether you maybe really ended up with duplicate items in the registry (e.g. by checking the output of http(s)://<openHAB>/rest/items)?

I get some hits in the json-db but I did not put them there

That could already be a really good starting point for the analysis. So if you can confirm that the indeed are duplicated, we "only" will have to figure out how they ended up in the wrong provider.

[martinvw]

That could already be a really good starting point for the analysis.

How can I view the file my Ubuntu reports it as binary?

PS: I believe it was temporarily resolved by a restart

[sjsf]

So this more or less rules out the possibility that the items ended up in the wrong provider. Which is the good news. Bad news is that we need another candidate...

PS: btw, the json-db files should be plain json files which you could use any text editor at. Only mapdb uses a binary format (where I would also have no idea how to look into properly)

[martinvw]

Then I found it in the mapDB most likely :-D I'll try check again tonight

[martinvw]

Okay, here I have it:

martinvw@elbrus:/meru/docker-configs/openhab$ grep -ri Coolcam_Plug | grep -v logs/events | grep -v logs/openhab.log
Binary file userdata/persistence/mapdb/storage.mapdb.p matches
conf/rules/coffeemachine.rules:    Item Coolcam_Plug_Energy_A changed or
conf/rules/coffeemachine.rules:    Item Coolcam_Plug changed
conf/rules/coffeemachine.rules:    if (Coolcam_Plug.state == OFF) {
conf/rules/coffeemachine.rules:     Coolcam_Plug_state.postUpdate(MODE_OFF)
conf/rules/coffeemachine.rules:    } else if (Coolcam_Plug_Energy_A.state < 0.1) {
conf/rules/coffeemachine.rules:     if (Coolcam_Plug_state.state == MODE_ACTIVE) Coolcam_Plug_state.postUpdate(MODE_FINISHED)
conf/rules/coffeemachine.rules:     else Coolcam_Plug_state.postUpdate(MODE_STANDBY)
conf/rules/coffeemachine.rules:    }  else if (Coolcam_Plug_Energy_A.state > 3.85) {
conf/rules/coffeemachine.rules:     Coolcam_Plug_state.postUpdate(MODE_ACTIVE)
conf/rules/coffeemachine.rules: } else if (Coolcam_Plug_Energy_A.state < 3.9) {
conf/rules/coffeemachine.rules:     Coolcam_Plug_state.postUpdate(MODE_STANDBY)
conf/items/zwave.items:Number Coolcam_Plug_Energy_W    "Plug - energy [%.2f W]"  (gSyncToOH2) { channel="zwave:device:f12de0b1:node8:meter_watts" }
conf/items/zwave.items:Number Coolcam_Plug_Energy_V    "Plug - energy [%.2f V]"  (gSyncToOH2) { channel="zwave:device:f12de0b1:node8:meter_voltage" }
conf/items/zwave.items:Number Coolcam_Plug_Energy_A    "Plug - energy [%.2f A]"  (gSyncToOH2) { channel="zwave:device:f12de0b1:node8:meter_current" }
conf/items/zwave.items:Number Coolcam_Plug_Total_Energy    "Plug - energy [%.2f kWh]"  (gSyncToOH2) { channel="zwave:device:f12de0b1:node8:meter_kwh" }
conf/items/zwave.items:Switch Coolcam_Plug           "Koffiezetapparaat"   (gSyncToOH2)                          { channel="zwave:device:f12de0b1:node8:switch_binary"}
conf/items/zwave.items:Number Coolcam_Plug_state "Koffiezetapparaat [MAP(coffeemachine_states.map):%s]" (gHistory) 
conf/sitemaps/_default.sitemap:             Switch item=Coolcam_Plug
conf/sitemaps/_default.sitemap:             Text item=Coolcam_Plug_state
conf/sitemaps/_default.sitemap:             Switch item=Coolcam_Plug
conf/sitemaps/_default.sitemap:             Text item=Coolcam_Plug_Energy_W
conf/sitemaps/_default.sitemap:             Text item=Coolcam_Plug_Energy_A
conf/sitemaps/_default.sitemap:             Text item=Coolcam_Plug_Energy_V
conf/sitemaps/_default.sitemap:             Text item=Coolcam_Plug_Total_Energy

[martinvw]

Okay, so it happens while viewing with habmin and paperUI while editing with Eclipse Smarthome Designer. I assume that does not create a .zwave.items file and if it does that is properly ignored now given earlier PR's.

I would assume this is my smart home version:

 98 | Active   |  75 | 0.9.0.201706012026     | Eclipse SmartHome Config XML
 99 | Active   |  80 | 0.9.0.201706012026     | Eclipse SmartHome Core
100 | Active   |  80 | 0.9.0.201706012026     | Eclipse SmartHome Core Audio
101 | Active   |  80 | 0.9.0.201706012026     | Eclipse SmartHome AutoUpdate Binding

[sjsf]

Okay, thanks.

As it is not persistent after a reboot, I would assume there items are not in the mapdb. It could still be some traces from the past, or a rule configuration why it is in there.

I will start looking into it tomorrow.

[martinvw]

Great, if you need anything or want me to enable specific logging just give a shout!

[sjsf]

Not necessary, I just ran into this situation myself. Unfortunately in my productive system, which did not have the debugger enabled. But nevertheless...

I attached a cleaned-up excerpt from my logs (unfortunately no debug enabled before): 2017-06-09_openhab.log.txt

Some interesting observations:

• I did several updates to the sjka.items file.
• There are two _really_ close ones (16:13:39.035 and 16:13:39.120), probably because of the remote filesystem. ModelRepositoryImpl synchronizes it by resourceSet - I'm a little surprised that it is _that_ quick, but let's assume this is correct
• Directly afterwards, some strange IllegalArgumentExceptions showed up. I don't think they are the root-cause, but they might be the first symptom.
• Let's ignore the Trådfri related exceptions, they also don't seem to be the root-cause and they are for sure not related
• There are further updates to the items file, but they are not that close, each of them again causing the same symptoms in the persistence layer.

Now I had a look at http://openhab/rest/items and indeed, they are duplicated. As we already know from your experience, the are not persisted in the database, so they cannot come from the ManagedItemProvider.

Here is a sample of one (or rather: two) items which I picked randomly:

{
  link: "http://openhab/rest/items/dg_rollladen_treppenhaus",
  state: "0.0",
  stateDescription: {
    pattern: "%d",
    readOnly: false,
    options: [ ]
  },
  type: "Rollershutter",
  name: "dg_rollladen_treppenhaus",
  label: "Rollladen Treppenhaus",
  tags: [ ],
  groupNames: [ ]
}

{
  link: "http://openhab/rest/items/dg_rollladen_treppenhaus",
  state: "0",
  stateDescription: {
    pattern: "%d",
    readOnly: false,
    options: [ ]
  },
  type: "Rollershutter",
  name: "dg_rollladen_treppenhaus",
  label: "Rolladen",
  category: "rollershutter",
  tags: [ ],
  groupNames: [
    "shadeSouth",
    "autoDOWN",
    "autoUP"
  ]
}

What you can see is that they are not identical: One has groups and a category, the other doesn't. Even more interesting: The labels are different! I didn't not rename any items recently, so this is a good clue. The GenericItemProvider always sets the category if there is one set in the DSL, I don't see how this could be skipped (unless the model awkwardly changes underneath). So I don't suspect him to have created the other one.

The different labels are suspect: My items file contains the shorter version. The long version seems to come from the thing (or rather: channel). The only ItemProvider that is left (which by some chance uses exactly this information) is the ChannelItemProvider which dynamically provides items for all links wich point to non-existing items. So it looks like we have to search for some constellations which could cause the ChannelItemProvider to do something stupid.

[martinvw]

Then I might have another hint in another topic :-D

https://community.openhab.org/t/design-pattern-time-of-day/15407/46

It looks like the file is first read empty:

2017-06-09 20:24:39.041 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'time_of_day.rules'
2017-06-09 20:24:39.042 [DEBUG] [er.antlr.AbstractInternalAntlrParser] - Parsing took: 0 ms
2017-06-09 20:24:39.045 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'time_of_day.rules' is either empty or cannot be parsed correctly!

Then a few 100 msec later:

2017-06-09 20:24:39.232 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'time_of_day.rules'
2017-06-09 20:24:39.234 [DEBUG] [er.antlr.AbstractInternalAntlrParser] - Parsing took: 2 ms

Do you think it is related?

[martinvw]

So it looks maybe like that the items are first removed because the file was just imported being empty (bug in the editor???) then the ChannelItemProvider recreates them. And then they are actually really reloaded and double.

[sjsf]

I'm now able to reproduce it every now and then even in the IDE. You are right, it apparently involves a broken model, at least it help me getting into that situation. And yes, of course the ChannelItemProvider jumps in if the model-items are gone - but it should clean them up again once the model-items come back.

It's still hard figuring out what _really_ happens because it only happens sometimes and I'm not even sure if it still happens when I set breakpoints, or if that "fixes" the behavior (a "Heisenbug" 😉 ). So I keep adding logs everywhere.

Nevertheless, it looks really weird: The ChannelItemProvider internally maintains an "items" list with all the items it created. Those who are duplicated are NOT IN THERE, but the registry has them. As if there is a path which does not notify the registry of the removal.

[martinvw]

It starts to sound like an exciting bug hunt :-D

Please keep me/us posted 👍

[sjsf]

Ha, I think I found the little bugger:
It's in the ChannelItemProvider lines 266+

When the GenericItemProvider reads the fixed items file in, it first creates the links (and adds the items later, be it the correct strategy or not - I think we can optimize this, but that's another story...). So the ChannelItemProvider gets notified about those updates here.

It then first removes the item from the items map and then informs its listeners (i.e. the registry) about it. The registry again informs _its_ listeners which happens to also be the ChannelItemProvider again, so it creates the item again (remember, the GenericItemProvider did not yet announce its model-items) and adds it correctly to the items map. When this notification chain returns to the first place, it _again_ removes the item from the map. So it lost track of it, but the registry still has it.

When I remove the second items.remove(key) it suddenly behaves well again. So now I will "only" have to figure out why it was in there, if it really is an accident or if it by chance works around another bug.

But that's nothing for tonight. Thanks for listening 😄

[sjsf]

As you wanted to be kept updated: I just started writing test-cases for this issue and by doing so I understood a little more about the mechanism.

It actually needs three things to cause this issue:

• The GenericItemChannelLinkProvider has some amnesia. It clears its context map, so it doesn't properly remember what it created/provided before. It needs an even number of updates, before a model removal can cause this issue (so it's not a heisenbug, it's just a 50% chance). Because of this amnesia, the ItemChannelLinks remain in the registry, therefore the ChannelItemProvider kicks in an creates the excess items.
• As said before, the ChannelItemProvider has a built-in amnesia due to the internal-remove/inform-and-thereby-recreate/internal-remove sequence which makes it impossible for it to remove its own item later on when the model gets loaded again (I have described this above). It just didn't surface so far because items from other providers seldomly come and go all the time.
• The question is why the ChannelItemProvider is part of this game at all... As the links for model items actually also come from the model, it actually should not need to. It would me much more clever of the GenericItemProvider if it would _first_ create the items and _then_ create the links (and vice versa for deletion) so that the ChannelLinkProvider will not need to become active at all. This I think is the root-cause for the long outstanding, somehow mysterious #2491, which is very annoying for all bindings which do something "expensive" stuff whenever a channel gets linked.

I prepared two commit to fix all this already, but as I said yesterday, I will need a bit more time to thoroughly test it before I create PRs for them.

[martinvw]

It needs an even number of updates, before a model removal can cause this issue (so it's not a heisenbug, it's just a 50% chance).

:-D

Great that you were able to track this down so quick and complete thanks!

[khan-git]

Good work.
This thing has been bugging me a lot.

[dotorg]

I'm not sure if this is a bug enough to warrant another issue ticket, but I ran into this as well. The issue I had was that the system doesn't seem to free up Group items when the items file that defined them has been updated.

To reproduce:

foo.items:

Group Foo
String Foo "Bar" (Foo)

(That's bad...)

Now change Group Foo:

Group Baz
String Foo "Bar" (Baz)

You'll still get this error, and if you look at /rest/items, you'll see the original group is still there.

Restarting fixes it.

[sjsf]

In what version did you experience this?

[dotorg]

The current 2.1 release, installed a few days ago.

On Fri, Dec 1, 2017 at 5:21 AM, Simon Kaufmann [e-mail]
wrote:

In what version did you experience this?

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
https://github.com/eclipse/smarthome/issues/3607#issuecomment-348457915,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ABrRgptDzZ9aRwqtJ-aCRUP59UFdIpSJks5s79MygaJpZM4NzMms
.