openhab / openhab1-addons

Add-ons for openHAB 1.x
Eclipse Public License 2.0
3.43k stars 1.7k forks source link

[UPB] Feature request -- receive status updates and scene changes from UPB devices. #4846

Open bracklanna opened 7 years ago

bracklanna commented 7 years ago

Request UPB binding enhancement to listen to status updates and scene (link) activation requests sent out by UPB devices, and then pass these updates into OpenHAB (i.e. as Events, or state changes.)

Current Behavior

At present, the UPB binding will SEND commands out to devices, and will receive ACK's (acknowedgments) from devices upon those specific commands being executed. But the UPB binding does not monitor status changes initiated at the UPB devices. (e.g. if someone presses a UPB light switch, even though the switch sends out a UPB status update on the UPB wire bus confirming that the light has changed from ON, to OFF, the OpenHAB UPB binding does not appear to register this update or do anything with it.)

Also, some UPB devices (e.g. scene controllers) can send out Scene activation commands. These also are ignored by the UPB binding.

Desired Behavior

If I physically activate a UPB wall switch ON, or OFF, OpenHAB should be notified of an Event or state change so that it can take action according to Rules.

If I physically activate a UPB Scene Control button, OpenHAB should be notified of the Scene (aka "link") activation status so that, if desired, it can take actions according to Rules.

Context

I have a UPB wall ON/OFF/Dimmer switch (model US11-40) in the bathroom. When someone enters the bathroom and turns on the light, I would like OpenHAB to know that, so that it can take the correct action according to ambient temperature. (In this case, either turn on the Vent only (warm weather) or turn on the Heater only (in winter), followed by Vent 5 minutes later.)

Another example: I have a UPB scene-control button set to dim all house lights to 15% for evening. When that UPB scene is activated (from the physical UPB device) I would like OpenHAB to be aware of the UPB scene change so that it can turn down the background music to evening volume levels.

Your Environment

DaAwesomeP commented 7 years ago

Are you sure that this is not a configuration issue? Just now I tested the following:

  1. I opened BasicUI and viewed status of light.
  2. I physically pressed UPB switch on the wall.
  3. I observed that the status updated.

I also know for sure that this works every time, as I am using an empty link/scene to control OpenHAB.

First, I would highly recommend updating to OH2 snapshot. You can then use PaperUI to download the most recent build of the binding. Otherwise, check that you are using this version.

Next, ensure that your devices are broadcasting when the switch status changes (easiest way is to put your ear to it and listen for the buzz when you press it). Set it to broadcast at least twice (this option is in another tab of the switches). As well as listening for commands as they happen, there is also a config option to set a polling interval in which it will ask all of the devices for their states.

Also, whenever a scene/link change is sent out by a switch, the switches affected by the scene don't broadcast their states; this is a limitation of UPB. So, OpenHAB will only be aware of the link changing but not the devices in it unless you make a rule for the link to adjust the states or wait for it to poll the switches.

cc @cvanorman

bracklanna commented 7 years ago

My bad for assuming this was not already implemented. I just checked and I am running that 1.9.0 version, same number of bytes in the JAR file (downloaded the one you suggested & cross-checked.)

I do have my devices set to broadcast and I can hear them buzz. I have debugging turned on & see no evidence of any incoming messages in the UPB binding logs, but I see outgoing messages (and lights on schedules, etc. are working) so -- I will look into this further.

When you say "update to OH2 snapshot" -- do you mean replace my entire OH 1.8.3 setup? There's no way I can do that on the fly, everything is working smoothly here and I need days or weeks to test any major change like that. If it is required in order to get this functionality, I will do it, but if this should be working in 1.8.3 I will stay with OH 1.8.3 for now.

Thanks again.

DaAwesomeP commented 7 years ago

I just checked and I am running that 1.9.0 version, same number of bytes in the JAR file (downloaded the one you suggested & cross-checked.)

Please compare checksums if you have not already to be extra sure. Previous builds (such as here) had the same filename.

I do have my devices set to broadcast and I can hear them buzz.

Please check that you can hear the PIM buzzing as well. Then, using the same USB-to-Serial adapter, plug in the PIM to a computer with UPStart. See if, when in icon view of the items, the icons change to reflect the state of the device as it changes.

If it is required in order to get this functionality, I will do it, but if this should be working in 1.8.3 I will stay with OH 1.8.3 for now.

I had this functionality working under 1.8.x as well, so you don't need to upgrade.

bracklanna commented 7 years ago

I compared checksums using 'md5sum' and got: 70b294af7b26d56a3fb715eaf9554734 org.openhab.binding.upb-1.9.0-SNAPSHOT.jar (Same checksum for your recommended version, and my currently-installed version.)

I believe the PIM is communicating properly (both send and receive,) based on these logs. Not sure what else to look for. Next I will try some bare-bones rules/items sets and see if I have some conflict going on there..(?).

My UPB network ID is: 97 The PIM is a Simply Automated RS232, firmware 4.17 (looks like a "1" but the printing is incomplete/hard to read..) connected through a SIIG JU-SC0111-S1 4-port USB serial adapter.

2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBBinding[:104]- Parsed UPB configuration: 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBBinding[:105]- Serial port: /dev/ttyUSB0 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBBinding[:106]- UPB Network: 97 2016-11-30 17:38:16 INFO o.o.b.upb.internal.UPBBinding[:74]- UPB binding starting up... 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 07106107FF3052. 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610AFF304F. 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 07106103FF3056. 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610DFF304C. 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 07106109FF3050. 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 07106105FF3054. 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610CFF304D. 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 07106101FF3058. 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106107FF3052 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 07106106FF3053. 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 07106104FF3055. 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 07106102FF3057. 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 07106108FF3051. 2016-11-30 17:38:16 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610BFF304E. 2016-11-30 17:38:17 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106107FF3052 ack timed out. 2016-11-30 17:38:17 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106107FF3052 2016-11-30 17:38:17 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106107FF3052 ack timed out. 2016-11-30 17:38:17 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106107FF3052 2016-11-30 17:38:18 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106107FF3052 ack timed out. 2016-11-30 17:38:18 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106107FF3052 2016-11-30 17:38:18 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106107FF3052 ack timed out. 2016-11-30 17:38:18 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610AFF304F 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [85, 48, 56] 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [48] 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [52, 54, 49, 70, 70, 48, 55, 56, 54, 48, 48] 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [48] 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [55, 13] 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PU080461FF07860007 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBBinding[:304]- Posting update: Light_FrontBed_Overhead,OFF 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610AFF304F ack timed out. 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610AFF304F 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [65, 13, 80, 78, 13, 80, 66, 13] 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PA 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PN 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBWriter[:127]- Message 0710610AFF304F not ack'd. 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610AFF304F 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PB 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBWriter[:127]- Message 0710610AFF304F not ack'd. 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610AFF304F 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [66, 13, 80, 75, 13] 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PB 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PK 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBWriter[:125]- Message 0710610AFF304F ack received. 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106103FF3056 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [65, 13] 2016-11-30 17:38:19 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PA 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [75, 13] 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PK 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBWriter[:125]- Message 07106103FF3056 ack received. 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610DFF304C 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [65, 13] 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PA 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [75, 13] 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PK 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBWriter[:125]- Message 0710610DFF304C ack received. 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106109FF3050 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [75, 13] 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PK 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBWriter[:125]- Message 07106109FF3050 ack received. 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106105FF3054 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [65, 13] 2016-11-30 17:38:20 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PA 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106105FF3054 ack timed out. 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106105FF3054 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [65, 13] 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PA 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106105FF3054 ack timed out. 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106105FF3054 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [78, 13, 80] 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PN 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBWriter[:127]- Message 07106105FF3054 not ack'd. 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106105FF3054 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [66] 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [13] 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PB 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBWriter[:127]- Message 07106105FF3054 not ack'd. 2016-11-30 17:38:21 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF304D 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [65, 13] 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PA 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [75, 13, 80, 66, 13] 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PK 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PB 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBWriter[:127]- Message 0710610CFF304D not ack'd. 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF304D 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [65, 13] 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PA 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [78, 13] 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PN 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBWriter[:127]- Message 0710610CFF304D not ack'd. 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF304D 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [65, 13] 2016-11-30 17:38:22 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PA 2016-11-30 17:38:23 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF304D ack timed out. 2016-11-30 17:38:23 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF304D 2016-11-30 17:38:23 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF304D ack timed out. 2016-11-30 17:38:23 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106101FF3058 2016-11-30 17:38:24 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106101FF3058 ack timed out. 2016-11-30 17:38:24 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106101FF3058 2016-11-30 17:38:24 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106101FF3058 ack timed out. 2016-11-30 17:38:24 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106101FF3058 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [85, 48, 56, 48, 53, 54, 49, 70, 70, 48, 49, 56, 54, 54, 52] 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [65] 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [56, 13] 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PU080561FF018664A8 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBBinding[:304]- Posting update: Light_Office_Desk_Lamp,ON 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106101FF3058 ack timed out. 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106101FF3058 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [78, 13, 80, 66, 13] 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PN 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBWriter[:127]- Message 07106101FF3058 not ack'd. 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PB 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106106FF3053 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106106FF3053 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [80] 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBReader[:178]- Received: [65, 13] 2016-11-30 17:38:25 DEBUG o.o.b.upb.internal.UPBReader[:148]- UPB Message: PA 2016-11-30 17:38:26 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106106FF3053 ack timed out. 2016-11-30 17:38:26 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106106FF3053 2016-11-30 17:38:26 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106106FF3053 ack timed out. 2016-11-30 17:38:26 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106106FF3053 2016-11-30 17:38:27 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106106FF3053 ack timed out. 2016-11-30 17:38:27 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106104FF3055 2016-11-30 17:38:27 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106104FF3055 ack timed out. 2016-11-30 17:38:27 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106104FF3055 2016-11-30 17:38:28 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106104FF3055 ack timed out. 2016-11-30 17:38:28 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106104FF3055 2016-11-30 17:38:28 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106104FF3055 ack timed out. 2016-11-30 17:38:28 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106104FF3055 2016-11-30 17:38:29 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106104FF3055 ack timed out. 2016-11-30 17:38:29 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106102FF3057 2016-11-30 17:38:29 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106102FF3057 ack timed out. 2016-11-30 17:38:29 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106102FF3057 2016-11-30 17:38:30 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106102FF3057 ack timed out. 2016-11-30 17:38:30 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106102FF3057 2016-11-30 17:38:30 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106102FF3057 ack timed out. 2016-11-30 17:38:30 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106102FF3057 2016-11-30 17:38:31 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106102FF3057 ack timed out. 2016-11-30 17:38:31 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106108FF3051 2016-11-30 17:38:31 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106108FF3051 ack timed out. 2016-11-30 17:38:31 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106108FF3051 2016-11-30 17:38:32 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106108FF3051 ack timed out. 2016-11-30 17:38:32 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106108FF3051 2016-11-30 17:38:32 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106108FF3051 ack timed out. 2016-11-30 17:38:32 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 07106108FF3051 2016-11-30 17:38:33 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 07106108FF3051 ack timed out. 2016-11-30 17:38:33 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610BFF304E 2016-11-30 17:38:33 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610BFF304E ack timed out. 2016-11-30 17:38:33 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610BFF304E 2016-11-30 17:38:34 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610BFF304E ack timed out. 2016-11-30 17:38:34 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610BFF304E 2016-11-30 17:38:34 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610BFF304E ack timed out. 2016-11-30 17:38:34 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610BFF304E 2016-11-30 17:38:35 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610BFF304E ack timed out. 2016-11-30 17:38:52 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610CFF205D. 2016-11-30 17:38:52 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:38:52 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610CFF205D. 2016-11-30 17:38:52 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:38:52 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:38:53 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:38:53 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:38:53 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:38:53 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:38:54 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:38:54 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:38:54 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:38:54 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:38:55 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:38:55 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:38:55 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:38:55 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:38:56 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:40:52 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610CFF205D. 2016-11-30 17:40:52 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:40:52 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:40:52 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:40:53 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:40:53 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:40:53 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:40:53 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:40:54 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:41:22 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610CFF205D. 2016-11-30 17:41:22 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:41:22 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:41:22 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:41:23 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:41:23 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:41:23 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:41:23 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:41:24 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:42:22 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610CFF205D. 2016-11-30 17:42:22 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:42:23 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:42:23 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:42:23 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:42:23 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:42:24 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:42:24 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:42:24 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:43:59 DEBUG o.o.b.upb.internal.UPBBinding[:104]- Parsed UPB configuration: 2016-11-30 17:43:59 DEBUG o.o.b.upb.internal.UPBBinding[:105]- Serial port: /dev/ttyUSB0 2016-11-30 17:43:59 DEBUG o.o.b.upb.internal.UPBBinding[:106]- UPB Network: 97 2016-11-30 17:44:09 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610CFF205D. 2016-11-30 17:44:09 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:44:09 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:44:09 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:44:10 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:44:10 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:44:10 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:44:10 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:44:11 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:46:04 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610CFF205D. 2016-11-30 17:46:04 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:46:04 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:46:04 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:46:05 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:46:05 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:46:05 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:46:05 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:46:06 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:47:04 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610CFF205D. 2016-11-30 17:47:04 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:47:04 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:47:04 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:47:05 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:47:05 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:47:05 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:47:05 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:47:06 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:48:04 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610CFF205D. 2016-11-30 17:48:04 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:48:04 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:48:04 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:48:05 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:48:05 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:48:05 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:48:05 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:48:06 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:49:04 DEBUG o.o.b.upb.internal.UPBWriter[:73]- Queueing message 0710610CFF205D. 2016-11-30 17:49:04 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:49:05 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:49:05 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:49:05 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:49:05 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:49:06 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed out. 2016-11-30 17:49:06 DEBUG o.o.b.upb.internal.UPBWriter[:165]- Writing bytes: 0710610CFF205D 2016-11-30 17:49:06 DEBUG o.o.b.upb.internal.UPBWriter[:130]- Message 0710610CFF205D ack timed o

DaAwesomeP commented 7 years ago

There are lots of ack timed out messages, which means that either the PIM never receives the ACK responses from the switches or the computer never reads them form the PIM. Without sending a message from the PIM, do you here the PIM buzz when a switch is physically pressed? Please try the test with UPStart to see if there is possibly an issue with the PIM or communication from the PIM to the computer. Also, it seems to receive many ore ACKs than non-OpenHAB-initiated status updates.

@cvanorman any comments?

bracklanna commented 7 years ago

Thanks for your prompt replies. The PIM blinks from amber (default state) to GREEN when sending out an OpenHAB-initiated command. The PIM blinks from amber to RED when receiving a switch-initiated transmission. So it looks like I have a problem at the physical layer, maybe a phasing issue or some such.

I will test further w/ UPStart etc. and reply back here either to ask further suggestions or report how the issue was resolved.

DaAwesomeP commented 7 years ago

@bracklanna be sure to run the noise and communication tests also included in UPStart.

bracklanna commented 7 years ago

I ran all the available tests in UPStart -- per-device tests, in-between device tests, repeating tests, etc. All came back with Noise figures of 0, signal quality Excellent, signal AT DEVICE averaging ~25, signal AT PIM averaging ~45.

I do have some devices on Other phase (standard 120V residential split-phase breaker panel), but all devices receive commands from UPStart reliably, and they also update their status (ON/OFF/Dim level) in the UPStart display panel properly too, so I know the status updates are getting back to the PIM.

It is strange that OpenHAB seems only to be sending out commands but not receiving responses. The commands it sends out to devices are completely reliable, probably 50 to 100 commands a day go out and take effect without any problems.

Will turning up the debug level to TRACE yield more information? Is that the highest level of debug info available? Thanks.

Any other suggestions to try?

DaAwesomeP commented 7 years ago

@bracklanna I can't really help you at this point. The only other possible factor I could think of would be the USB-to-Serial adapter and how if may behave on Linux, but that is very unlikely, as those sorts of devices rarely have driver issues on Linux. You should definitely try turning up the logs all the way.

bracklanna commented 7 years ago

Thank you, I appreciate all your help up to this point. I will keep at it and update here when I figure it out.

bracklanna commented 7 years ago

I don't expect any further reply unless something dawns on you, but looking through the logs above, indeed the UPBReader thread does successfully receive ACK messages to some commands. It seems this happens only right after killing & restarting OpenHAB. It receives a few ACKs (indicating likely no issue with the PIM, the USB-serial converter, etc.,) and then stops receiving any further ones for the rest of that OpenHAB run (minutes, hours, days..)

I wonder if I'm hitting some obscure bug in the UPB binding that is choking on a particular command or sequence of commands. Something like the "can't use network IDs larger than 127" bug mentioned in other comments -- non-obvious, but significant.

I turned up the debugging level to "TRACE" but nothing more appears in the UPB logs.

DaAwesomeP commented 7 years ago

It seems this happens only right after killing & restarting OpenHAB.

This makes me feel as if there is some issue with the serial port hanging.

Something like the "can't use network IDs larger than 127" bug mentioned in other comments

This was patched in the latest version of the binding. The bug would prevent you from sending commands too.