Issue loading .items files

Hi,

Hopefully some one shed some light on this issue I’m having with my Google Assistant integration which looks like it’s originating from the REST API end point.

I have defined an item as follows:

Group:Color GF_LivingRoom_Lights “Living Room Lights [%s]” (gLights, GF_Lights, GF_LivingRoom) [“Lighting”]

The Item docs state if you don’t specify a group function, it defaults to EQUALITY.

However when I try to send a command I see the following in the logs:

2019-12-03 20:42:09.187 [WARN ] [rest.core.internal.item.ItemResource] - Received HTTP POST request at 'items/GF_LivingRoom_Lights' with an invalid status value 'OFF'.

As far as I can tell, sending an ‘OFF’ command to a Color Item is perfectly legitimate - why is this a problem with a Group Color Item?

Edit:

Some more details - I’m on snapshot build #1767
Editing my .items file seems to have fixed it - I wonder if some bundle hadn’t loaded when my items file was parsed initially.

Works for me, REST API OH 2.4
You may have to share your POST

I’ve forced a reload of my .items file and it seems to work now…

Something similar happened again today after updating to latest snapshot.

2019-12-04 16:09:30.798 [INFO ] [rest.core.internal.item.ItemResource] - Received HTTP POST request at 'items/Automatic_Light_Control' for the unknown item 'Automatic_Light_Control'.

So I did some investigation:

pi@raspberrypi:~ $ cat /etc/openhab2/items/*.items | grep "Automatic_Light_Control"
Switch Automatic_Light_Control          "Automatic Lighting Control" (Home) ["Switchable"]
pi@raspberrypi:~ $ cd /etc/openhab2/items
pi@raspberrypi:/etc/openhab2/items $ nano lights.items
pi@raspberrypi:/etc/openhab2/items $ touch lights.items

Which triggered the following:

==> /var/log/openhab2/openhab.log <==

2019-12-04 16:11:24.054 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'lights.items'

==> /var/log/openhab2/events.log <==

2019-12-04 16:11:24.079 [vent.ItemStateChangedEvent] - Automatic_Light_Control changed from NULL to ON

2019-12-04 16:11:24.087 [vent.ItemStateChangedEvent] - GF_DiningRoom_Chandelier changed from NULL to OFF

2019-12-04 16:11:24.102 [vent.ItemStateChangedEvent] - GF_DiningRoom_Wall_Lights_Brightness changed from NULL to 0

2019-12-04 16:11:24.112 [vent.ItemStateChangedEvent] - GF_DiningRoom_Wall_Lights_Temperature changed from NULL to 71

2019-12-04 16:11:24.118 [vent.ItemStateChangedEvent] - GF_LivingRoom_Chandelier changed from NULL to OFF

2019-12-04 16:11:24.129 [vent.ItemStateChangedEvent] - GF_LivingRoom_Wall_Lights_Brightness changed from NULL to 0

2019-12-04 16:11:24.143 [vent.ItemStateChangedEvent] - GF_LivingRoom_Wall_Lights_Temperature changed from NULL to 71

2019-12-04 16:11:24.169 [ome.event.ItemUpdatedEvent] - Item 'GF_LivingRoom_Lights' has been updated.

2019-12-04 16:11:24.180 [ome.event.ItemUpdatedEvent] - Item 'GF_DiningRoom_Lights' has been updated.

2019-12-04 16:11:24.191 [ome.event.ItemUpdatedEvent] - Item 'GF_Lights' has been updated.

2019-12-04 16:11:24.201 [ome.event.ItemUpdatedEvent] - Item 'FF_Lights' has been updated.

2019-12-04 16:11:24.212 [ome.event.ItemUpdatedEvent] - Item 'GF_Hallway_Lights' has been updated.

Which then allowed me to control the item:

2019-12-04 16:11:49.634 [ome.event.ItemCommandEvent] - Item 'Automatic_Light_Control' received command OFF
2019-12-04 16:11:49.643 [vent.ItemStateChangedEvent] - Automatic_Light_Control changed from ON to OFF

Today I noticed that my motion sensors weren’t triggering the rules when the state changed. In short - I think there is some issue parsing .items files - maybe it times out on startup.

To investigate, I did a GET from the REST API on the item which should have (but failed) triggered the automated lighting.

{
    "members": [],
    "link": "http://192.168.0.44:8080/rest/items/GF_Hallway_Motion",
    "state": "OFF",
    "stateDescription": {
        "pattern": "%s",
        "readOnly": false,
        "options": []
    },
    "editable": false,
    "type": "Group",
    "name": "GF_Hallway_Motion",
    "label": "Hallway motion",
    "tags": [],
    "groupNames": [
        "GF_Hallway",
        "gMotion"
    ]
}

This item is a group that actually aggregates two motion sensors (one upstairs and one downstairs) but as it stands, it tells me there are no members in this group.

Group:Switch:OR(ON,OFF) GF_Hallway_Motion               "Hallway motion [%s]"                   (GF_Hallway, gMotion)
Switch                  GF_Hallway_Downstairs_Motion    "Hallway (downstairs) motion [%s]"      (GF_Hallway, GF_Hallway_Motion)         {channel="mqtt:topic:mymqttbroker:hallway_motion_sensor_1:motion"}
Switch                  GF_Hallway_Upstairs_Motion      "Hallway (upstairs) motion [%s]"        (GF_Hallway, GF_Hallway_Motion)         {channel="mqtt:topic:mymqttbroker:hallway_motion_sensor_2:motion"}

So I ran the following command:

touch /etc/openhab2/items/*.items

I then followed this by doing another GET on the same item:

{
    "members": [
        {
            "link": "http://192.168.0.44:8080/rest/items/GF_Hallway_Downstairs_Motion",
            "state": "OFF",
            "stateDescription": {
                "pattern": "%s",
                "readOnly": true,
                "options": []
            },
            "type": "Switch",
            "name": "GF_Hallway_Downstairs_Motion",
            "label": "Hallway (downstairs) motion",
            "tags": [],
            "groupNames": [
                "GF_Hallway",
                "GF_Hallway_Motion"
            ]
        },
        {
            "link": "http://192.168.0.44:8080/rest/items/GF_Hallway_Upstairs_Motion",
            "state": "OFF",
            "stateDescription": {
                "pattern": "%s",
                "readOnly": true,
                "options": []
            },
            "type": "Switch",
            "name": "GF_Hallway_Upstairs_Motion",
            "label": "Hallway (upstairs) motion",
            "tags": [],
            "groupNames": [
                "GF_Hallway",
                "GF_Hallway_Motion"
            ]
        }
    ],
    "groupType": "Switch",
    "function": {
        "name": "OR",
        "params": [
            "ON",
            "OFF"
        ]
    },
    "link": "http://192.168.0.44:8080/rest/items/GF_Hallway_Motion",
    "state": "OFF",
    "stateDescription": {
        "pattern": "%s",
        "readOnly": false,
        "options": []
    },
    "editable": false,
    "type": "Group",
    "name": "GF_Hallway_Motion",
    "label": "Hallway motion",
    "tags": [],
    "groupNames": [
        "GF_Hallway",
        "gMotion"
    ]
}

So it’s clear to see that although OH initially parsed my item files and created the group, it did not correctly parse all items in all files and complete the processing i.e. adding them to the group.

There are long standing issues with sequencing of various files and services during system start up. e.g. you might get rules running before Items used are defined.

So far as I know this is just about timing, these do not result in things getting missed altogether, which is what you seem to be reporting.
If there were an item.file parsing problem, it should tell you so in openhab.log. You have looked in there? Every items file should make a “loaded” message.

It’s possible to manipulate group memberships post-boot with the REST API. Confident this is not self-inflicted?

100%. The only thing that would interact with the OH REST API is Google Home/Assistant Integration through myopenHAB, which shouldn’t be manipulating group membership.

Here is a snippet from the openhab.log during OH startup (37 files “loaded”):

2019-12-04 12:28:01.526 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'calendar.items'
2019-12-04 12:28:01.578 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'devices.items'
2019-12-04 12:28:01.607 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'webos.items'
2019-12-04 12:28:01.697 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'second_bedroom.items'
2019-12-04 12:28:01.709 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'eos.items'
2019-12-04 12:28:01.772 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'openweather.items'
2019-12-04 12:28:01.802 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'porch.items'
2019-12-04 12:28:01.816 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lights.items'
2019-12-04 12:28:01.839 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'heating_test.items'
2019-12-04 12:28:01.852 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'media.items'
2019-12-04 12:28:01.863 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sideentry.items'
2019-12-04 12:28:01.872 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'discovery.items'
2019-12-04 12:28:01.880 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'idealarm.items'
2019-12-04 12:28:01.896 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rooms.items'
2019-12-04 12:28:01.911 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'weather.items'
2019-12-04 12:28:01.928 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'wunderground.items'
2019-12-04 12:28:01.947 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'energy.items'
2019-12-04 12:28:01.961 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'speedtest.items'
2019-12-04 12:28:01.977 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'masterbedroom.items'
2019-12-04 12:28:01.988 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hyperion.items'
2019-12-04 12:28:02.000 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'frontroom.items'
2019-12-04 12:28:02.009 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'tasmota.items'
2019-12-04 12:28:02.020 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kitchen.items'
2019-12-04 12:28:02.029 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alerts.items'
2019-12-04 12:28:02.042 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.items'
2019-12-04 12:28:02.055 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'network.items'
2019-12-04 12:28:02.065 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alexa.items'
2019-12-04 12:28:02.074 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'systeminfo.items'
2019-12-04 12:28:02.082 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'chromecast.items'
2019-12-04 12:28:02.094 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hallway.items'
2019-12-04 12:28:02.106 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'backroom.items'
2019-12-04 12:28:02.114 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'presence.items'
2019-12-04 12:28:02.122 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'harmony.items'
2019-12-04 12:28:02.131 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'heating.items'
2019-12-04 12:28:02.141 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'location.items'
2019-12-04 12:28:02.150 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'conservatory.items'
2019-12-04 12:28:02.157 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonyavr.items'

And here is when I did a touch on the item files (again, 37 files “loaded”):

2019-12-05 11:32:41.866 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'alerts.items'
2019-12-05 11:32:41.997 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'backroom.items'
2019-12-05 11:32:42.141 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'astro.items'
2019-12-05 11:32:42.764 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'calendar.items'
2019-12-05 11:32:43.174 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'alexa.items'
2019-12-05 11:32:43.278 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'discovery.items'
2019-12-05 11:32:43.343 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'eos.items'
2019-12-05 11:32:43.631 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'devices.items'
2019-12-05 11:32:44.737 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'conservatory.items'
2019-12-05 11:32:44.831 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'chromecast.items'
2019-12-05 11:32:44.992 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'harmony.items'
2019-12-05 11:32:45.085 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'hallway.items'
2019-12-05 11:32:45.357 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'hyperion.items'
2019-12-05 11:32:45.463 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'frontroom.items'
2019-12-05 11:32:45.822 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'energy.items'
2019-12-05 11:32:46.479 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'kitchen.items'
2019-12-05 11:32:46.664 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'idealarm.items'
2019-12-05 11:32:46.694 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'heating_test.items'
2019-12-05 11:32:46.980 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'network.items'
2019-12-05 11:32:47.121 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'heating.items'
2019-12-05 11:32:47.530 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'openweather.items'
2019-12-05 11:32:49.833 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'media.items'
2019-12-05 11:32:50.310 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'masterbedroom.items'
2019-12-05 11:32:50.792 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'location.items'
2019-12-05 11:32:50.937 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'second_bedroom.items'
2019-12-05 11:32:51.326 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'rooms.items'
2019-12-05 11:32:51.585 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'presence.items'
2019-12-05 11:32:51.636 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'porch.items'
2019-12-05 11:32:51.776 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'systeminfo.items'
2019-12-05 11:32:51.827 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'speedtest.items'
2019-12-05 11:32:51.963 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'sonyavr.items'
2019-12-05 11:32:52.012 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'sideentry.items'
2019-12-05 11:32:52.213 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'wunderground.items'
2019-12-05 11:32:52.661 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'webos.items'
2019-12-05 11:32:52.726 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'weather.items'
2019-12-05 11:32:52.734 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'tasmota.items'

Though my issues suggest that something went wrong during the loading of the files during startup, or some sequence of events during startup manipulated them.

Your list of files doesn’t mean much to me, but it’s not going to help even if you point out those involved in your problematic group.

Maybe you have stressed some part of the group parsing process; I doubt many users have that many items files, and those that do are probably on more powerful boxes.
Going to be difficult to pin down.