Weird postCommand issue, looking for ideas how to diagnose

Setup, Configuration and Use Scripts & Rules
1

I’ve got a cron-based rule that has a very simple postCommand call on it.

The rule is pretty simple:

rule "Breezeway Split On"
when
    Time cron "0 0 5 1/1 * ? *"
then
    BreezewayIRBlasterFujitsu_FujitsuPower.sendCommand(ON)
end

The problem I’m having (and its not just this rule, I’ve got a couple of related ones) – the rule, at least according to the logs, sends the command. That said, they don’t work. There’s no logging from the binding showing it ever received it.

When the rule runs, I get the ItemStateChangedEvent:

2018-12-17 05:00:00.077 [ome.event.ItemCommandEvent] - Item 'BreezewayIRBlasterFujitsu_FujitsuPower' received command ON

Nothing actually happens, though.

If I send “ON” via a sitemap, the logging is different:

2018-12-17 06:59:20.707 [ome.event.ItemCommandEvent] - Item 'BreezewayIRBlasterFujitsu_FujitsuPower' received command ON
2018-12-17 06:59:20.717 [nt.ItemStatePredictedEvent] - BreezewayIRBlasterFujitsu_FujitsuPower predicted to become ON
2018-12-17 06:59:20.727 [vent.ItemStateChangedEvent] - BreezewayIRBlasterFujitsu_FujitsuPower changed from OFF to ON
2018-12-17 06:59:20.739 [me.event.ThingUpdatedEvent] - Thing 'xxx:xxx:xxx' has been updated.

Notice when the sitemap does it, it follows the normal prediction / changed pattern, and then the thing is logged as being updated.

Its a custom binding, but the very first line of the handleCommand implementation logs a debug line, which I see in the latter case and not in the former case, so I don’t think this is something happening in the binding – its something in the OH environment, and I’ve got no clue where to even begin to diagnose it. Are there any better logging levels I can enable that might catch what OH is doing between the item receiving the command, and the process of it letting the Thing know?

2

Just for another point of contact, make a rule that triggers from received command and logs it, to see if command gets on bus.

Item definition might be useful.

3

That’s a good thought, I’ll see if another rule sees the command.

The item itself isn’t interesting – its just String item, with a label and a channel, and the channel is correct because directly triggering the item via BasicUI or sending the command via Karaf both work reliably. And because the channel isn’t part of a public binding, its channel name wouldn’t mean anything.

4

It would be cool to share it…

5

It wouldn’t be of any use. Its a custom binding, talking a custom TCP socket and HTTP protocol, to custom firmware running on an ESP8266 using supporting hardware installed on a custom-fabricated PCB.

Its on my list, someday, to look at replacing this binding and a few others I’ve got with a single binding that does auto-device and auto-service discovery via a standardized Arduino library over SSDP/UPnP to replace the custom stacks all these devices are using, but thats a lot of work for a half dozen firmware versions installed on a couple dozen devices that all are working, anyway. Or I might just update the HTTP binding to support websocket, since most of the things I’m doing only need a custom binding because of how the event listeners work.

6

So interestingly, the rules show the exact same thing … when triggered from PaperUI, the two new rules run, indicating that the command was received, and the handleCommand() method is hit on the binding, and everything updates correctly.

13:30:47.018 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'BreezewayIRBlasterFujitsu_FujitsuPower' received command ON
13:30:47.028 [DEBUG] [aster.handler.IrBlasterFujitsuHandler] - handleCommand: xxx:xxx:xxx:xxx:fujitsu:fujitsu-power -> ON
13:30:47.029 [INFO ] [arthome.event.ItemStatePredictedEvent] - BreezewayIRBlasterFujitsu_FujitsuPower predicted to become ON
13:30:47.051 [DEBUG] [.eclipse.smarthome.model.script.Rules] - Received power command on BreezewayIRBlasterFujitsu_FujitsuPower
13:30:47.064 [INFO ] [smarthome.event.ItemStateChangedEvent] - BreezewayIRBlasterFujitsu_FujitsuPower changed from OFF to ON
13:30:47.067 [DEBUG] [.eclipse.smarthome.model.script.Rules] - Changed on BreezewayIRBlasterFujitsu_FujitsuPower

Triggered by the rule:

2018-12-17 13:30:00.045 [ome.event.ItemCommandEvent] - Item 'BreezewayIRBlasterFujitsu_FujitsuPower' received command ON
2018-12-17 13:30:00.075 [DEBUG] [eclipse.smarthome.model.script.Rules] - Received power command on BreezewayIRBlasterFujitsu_FujitsuPower

So its the exact same behavior very consistently – when the command is sent by the rule, it never hits the Thing, but when PaperUI sends it or karaf sends the command via smarthome:send, it works fine.

Its a head-scratcher …

7

Well, we have a secret Item having trouble with a secret binding.

Less flippantly, the command is obviously getting shared on the OH bus, and I’ve not seen anyone else reporting anything like this. Binding looks suspect in the way it is bound to the Item.

Tagging this thread as a binding development issue may attract the right interest.

8

I think it is time to raise an issue on Github

9

Yes, I know there’s an item having trouble with a binding. I said that in my first post, my question isn’t “what is wrong with this”, it was what logging or other diagnostics may be available that aren’t clearly documented (since most of ESH is, at its core, not well documented) that people may know to figure out what was going on.

Something is happening between the message with a simple “ON” being sent to the event bus and it being sent to the ThingHandler that is causing it not to get delivered to the handler, and only when its coming from a rule – every other interface delivers it correctly. What details people might know about related to the rule engine between execution and events hitting the thing might give me a clue where to look. Running microservice systems like ESH in a debugger is nearly useless, so a debugger isn’t an option.

My next step is to post in ESH’s forums, but these get 100x the traffic they do, and the majority of knowledge about ESH is over here, not over there just because this is where people are actually using it.

FWIW, I’ve seen symptomatically similar behavior going from rules into the ZWave binding a few times during the period of time the ZWave binding is refreshing the network immediately after startup (commands hitting the event bus, but never being processed by the things bound to the Z-wave channels). So I’m not entirely sure the problem is isolated to the binding, particularly because it seems to have cropped up in 2.4.

10

So, actually I just figured out what the issue was and, as I suspect, it wasn’t something in the binding, but a differing behavior in the rules engine, seemingly related to how Xtend does type conversions.

From what I can tell, all the other interfaces will take a string like “ON” and convert it to an OffOnType if a channel is configured as one, but will pass it as a StringType if not. The rules engine (at least in 2.4) is not doing that. sendCommand(ON) is sending it as a OnOffType, and there’s no error messaging if thats not correct.

The only logging about that scenario is DEBUG logging down in an internal class in ESH. You need to enable DEBUG logging in org.eclipse.smarthome.core.thing.internal, and then AutoUpdateManager will conveniently tell you what the issue is:’

2018-12-18 14:31:30.048 [DEBUG] [ore.thing.internal.AutoUpdateManager] - Received prediction of a not accepted type (OnOffType) for item BreezewayIRBlasterFujitsu_FujitsuPower
2018-12-18 14:31:30.067 [DEBUG] [ore.thing.internal.AutoUpdateManager] - Received update of a not accepted type (OnOffType) for item BreezewayIRBlasterFujitsu_FujitsuPower
2018-12-18 14:31:30.092 [DEBUG] [.thing.internal.CommunicationManager] - Received not accepted type 'OnOffType' for channel 'xxx:xxx:xxx:xxx:fujitsu:fujitsu-power'
2018-12-18 14:31:30.100 [DEBUG] [.thing.internal.CommunicationManager] - Received event 'ON' (OnOffType) could not be converted to any type accepted by item 'BreezewayIRBlasterFujitsu_FujitsuPower' (String)

One would argue an OnOffType should just silently change to a StringType in that scenario, but regardless, that was the issue. sendCommand(“ON”) works, sendCommand(ON) does not, and apparently Karaf, and the REST API handles that in some way that is more robust (I presume, but haven’t checked, that they look at the item definition, which is String, and do the type conversion, rather than taking a guess at it the way the rules engine seems to do)

11

That would be because the REST API and karaf can only accept plain text, while the rule engine uses objects. When the request is received at the REST API it tries to make sense of the String that is passed with the request and convert it to a appropriate type that the item can handle. If you are using a String item no conversion is needed and the plain String can be passed as a command. If you send an OnOffType.ON to a String item it can’t handle the passed object, since it can only handle Strings.

Seems to me everything works as intended.

12

I hesitate to say that if we had been shown the secret Item the problem would have been obvious …

13

Well, the bigger issue is that there’s no error logging for that scenario. There’s a more fundamental issue with Xtend, in general, in that its a strongly typed environment that doesn’t expose strong types, and doesn’t have a compile phase with type safety to catch things like that the way C# (or even Lombok, in Java) handle var types. So its a bigger problem if there’s a silent boxing and unboxing happening in inconsistent ways and consumers silently swallow errors when its not done correctly. Again, my question wasn’t “what’s the problem”, it was a more generic “how do you diagnose this class of problems?” – the answer being, at that point, turning on DEBUG logging because there’s error conditions that are being logged as DEBUG down in ESH. Asking what the problem was would obviously be stupid if nothing about the environment was visible to anyone else.

Now, I’d also argue the boxing isn’t behaving in a logical, and potentially consistent way, because what the system does with the unquoted parameters depends on the target type, and the system does know that the target in this case was a String. For “ON” to turn into OnOffType, something is picking that out and inferring the type, just as 23 turns into a BigDecimal and 45C turns into a QuantityType. (In fact, for a QuantityType channel, 23 seems to also turn into one).

What the system should probably be doing, at a minimum, is either validating types at rule parse time (which it could, in theory, do because it knows the channel types) or properly erroring if you send a command of the wrong type to a channel. The latter, I’d bet, is a common mistake people make in rules. In fact, a quick search shows lots of posts of people doing that. There’s three debug lines in CommunicationManager.handleEvent that probably should be ERROR, or WARN levels, not DEBUG. (Unless something else catches it and logs it, the same scenario happens in there if you send a command to a item with a typo in its channel definition.)

14

That I can agree with, I would have expected some warning when a command is sent to an item that doesn’t support that command type, preferably when the rule is parsed and a type mismatch is detected, but otherwise as a warning in the log when the command is sent.

Raise an issue in the eclipse smartphone repo (even better if you can make a PR for it as well), and I’m sure something can be implemented. I would guess that noone has thought it would be a big problem.

15

A String item takes a string command
But I agree, an error message should pop up

16

I don’t know. There are legitimate cases to send commands that “don’t fit” the Item. Trivial example, sending ON to a dimmer 0-100%. People would grizzle if that generated a WARN, no doubt! It’s a trivial example because everyone knows about it and code is written to accommodate it.

Prescriptively deciding what is allowed seems not very " openHAB.". Take the further example of the REFRESH command - it’s up to the binding implementer whether to accept or act on that. But it should not interfere or warn - other bindings might be happy to deal with it.

17

The way the system works right now, either the binding is explicitly accepting OnOffType for that channel, or the command isn’t working. If the command isn’t working, that’s the whole point of it being a WARN.

Baked into the core event dispatcher of ESH is code the explicitly means you can’t send OnOffType to a DecimalType channel. If you can, then there’s already code special-casing that condition either in OH or in ESH (which there seems to be – something is calling the as() method on the type). Because that code is there, its already arbitrary which conversions are happening – autoconverting an OnOffType to a String when the channel accepts String is no weirder than converting an OnOffType to a DecimalType – less so, in fact, because all the serialization mechanisms are already doing it.

I mean, look at the code of OnOffType – its convering On to white, which is completely arbitrary.

Based on your argument, the system shouldn’t be doing any of those – if you want to set a PercentType to 100%, you should be sending a PercentType, not having the last developer who worked on the code arbitrarily decide which conversions should happen, and if anything else it sent, it should silently ignore it. The way it is right now, in fact, is far worse – because not only do invalid types not get logged, you have no way of knowing which types actually will convert without going through the Java code or trying it, and trying it isn’t definitive if you don’t trust the entire stack 100% end-to-end.

Its not like there’s documentation saying that OnOffType will be autoconverted by the framework into DecimalType (as 1 or 0), PercentType (as 100 or zero), or HSBType (white or black).

Edit: I should clarify, too, that changing those log lines wouldn’t generate a WARN in your example, because you’re not sending an OnOffType – its already been converted to PercentType or HSBType.

18

Okay, beyond my knowledge. I believed, apparently wrongly, that ON could arrive at a binding dimmer channel and the binding decided if that meant 100% or restore-last-brightness (because that’s device dependent).

Not arbitrary - there is a published table of what Item types accept what commands.

There’s certainly a case to make an enhancement request that disallowed command types for an Item raise a warning, if the framework truly doesn’t allow them through to bindings where “special action” could be desirable.

And/or, that ONOFFtype sent to String gets converted to “ON”, seems reasonable.

20

Oops. What the heck did I just do? Ack.

21

Okay, beyond my knowledge. I believed, apparently wrongly, that ON could arrive at a binding dimmer channel and the binding decided if that meant 100% or restore-last-brightness (because that’s device dependent).

Until I dug into ESH’s code, it wasn’t obvious, either. I’m assuming that’s why the Zwave binding, for example, exposes a OnOffType-bound channel and a PercentType-bound channel for dimmers. ON sent to the latter goes to 100%, ON to the former is device-dependent. (Another weird, and undocumented, inconsistency – which I assume is because of this framework limitation)

Not arbitrary - there is a published table of what Item types accept what commands.

That’s precisely why it is arbitrary. The binding has no say on it – the Item accepts one, and only one, type. The framework as an arbitrary set of conversions its doing, which only sense with whatever usecase they were originally added for. The fact that you need two channels to control a Z-wave dimmer properly is because ON is going to convert to PercentType(100), and would make it impossible to do a “ON to last value”. And the user, without knowing ESH is doing that, wouldn’t know why.

The architecture, as implemented, in ESH is just plain bad because the framework is defining a limited set of conversions and as a binding author you can’t do a thing about it. Even ignoring the appropriateness of logging a warning when you get it wrong, or the appropriateness of having as() on the enum-derived types universally support String as an output, the real problem is that the ESH binding framework can’t expose a channel as multiple types, so binding authors can’t overload the operations in a binding-appropriate way, and they’re stuck with the fallout of the conversions the framework is doing. (I haven’t looked, but presumably the bindings that do RGB lights need a separate channel to turn on to a preset or previous color, given that OnOffType converts to WHITE – another point of potential confusion to rule authors.)

While this is way out of scope for an OH discussion, IMO the system should deprecate the as() method, and extend the type metadata to support a “item-type-supports” property.

For example, this is the channel definition for the one above:

<channel-type id="fujitsu-power">
	<item-type>String</item-type>
	<label>Power Mode</label>
	<state>
		<options>
			<option value="OFF">Off</option>
			<option value="ON">On</option>
			<option value="ECONOMY">Economy</option>
			<option value="MINHEAT">Mininum Heat</option>
			<option value="POWERFUL">Powerful</option>
		</options>
	</state>
</channel-type>

(Note, I probably could’ve done this as an enum as well, but the way to do that isn’t documented, and until I looked at how the built-in types were implemented, it wasn’t clear you could do that)

Now, ideally, I could do something like:

<channel-type id="fujitsu-power">
	<item-type>String</item-type>
    <item-type-supports>OnOffType,DecimalType</item-type-supports>
	<label>Power Mode</label>
	<state>
		<options>
			<option value="OFF">Off</option>
			<option value="ON">On</option>
			<option value="ECONOMY">Economy</option>
			<option value="MINHEAT">Mininum Heat</option>
			<option value="POWERFUL">Powerful</option>
		</options>
	</state>
</channel-type>

And then have the system send me any commands of those types – then I can do domain-specific conversions. The handleCommand() method takes a Command, anyway, so you can send any type you want into it. Its just a framework limitation that keeps channels 1:1 bound to a type.

Anyway, its an aside, but that’s how I think it should work. I don’t know if it ended up the way it is because of developmental inertia or an explicit decision, but its a weird and inconsistent spot its ended up.