Transformation of generic thing channel stops working

[DrRSatzteil]

I have setup two generic enocean things in openHAB (only these two) and I use a JS transformation to transform the messages 1:1 from the device to the string channel of the thing.

From time to time I see this strange behaviour: the messages from the physical sensors are processed by the binding (I can see the processing log messages in the trace logs) but the string channel does not fire an event anymore. This means that none of the messages sent by this device are coming through to the item level until I restart openHAB. I don't see anything suspicious in the logs at all. After a restart of OH everything is working as expected again so I'm pretty sure that the sensors are working just fine....

This is not related to my other issue related to serial reconnections. This problem occurs with WiFi being constantly switched on respectively a stable serial connection. Since I see messages coming in communication between sensor and OH can be ruled out as source of this issue as well. It seems that something breaks in the binding from time to time

[DrRSatzteil]

Just a quick update: After I've seen the behaviour described above in two consecutive days, today everything went smoothly from the early morning till late at night... I'll keep on monitoring this and close the issue if the problem does not longer appear. I hope that this will be the case since it would be really hard to debug this...

[fruggy83]

Hi Thomas, do you still see the message "ESP Packet payload {} for {} received" when this happens? Maybe the handler got disposed because of an error. I could add some more log messages in the generic message transformation.

[DrRSatzteil]

Hi, yes I still see these messages so in the logs so everything seems completely normal. The sensors I am using send a message every 15 minutes and I see those in the logs. Some more logging could be helpful indeed. But since I opened this issue the problem has no longer occurred so even with some more logging I would have to wait until I see this behaviour again.

[DrRSatzteil]

Had this issue again yesterday and today. Seems this is mostly related to OH restarts which I do every morning due to the reconnect issue I opened. In some cases I do see the behaviour as described above. So far this could be fixed with another restart of the OH container.

[DrRSatzteil]

Another thing I noticed over the last couple of days: I currently have only two enocean devices. However this issue does not necessarily affect both devices at the same time. I sometimes receive events for one device but not for the other. This could be resolved by OH restarts (sometimes more than one restart is required)

[DrRSatzteil]

I just switched to openHAB 3.1M4 build to see if this brings improvements for my problems. The situation is still the same. I see messages from my sensors in the log file but the transformation is not triggered for some reason.

Find below the log of my M4 instance after an upgrade and another reboot. The last three messages were messages from my sensors but the transformation for 0589700D not been triggered/my item is still unchanged. The last message of 058A42A4 triggered transformation and my item was updated.

2021-05-12 09:06:03.372 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2021-05-12 09:06:03.373 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:genericThing:160542a4f3:058A42A4 bridge status OFFLINE
2021-05-12 09:06:03.375 [INFO ] [ernal.transceiver.EnOceanTransceiver] - EnOceanSerialTransceiver RX thread started
2021-05-12 09:06:03.375 [INFO ] [nternal.handler.EnOceanBridgeHandler] - EnOceanSerialTransceiver RX thread up and running
2021-05-12 09:06:03.376 [DEBUG] [nternal.handler.EnOceanBridgeHandler] - request base id
2021-05-12 09:06:03.379 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2021-05-12 09:06:03.379 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:genericThing:160542a4f3:0589700D bridge status OFFLINE
2021-05-12 09:06:03.380 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Enqueue new send request with ESP3 type COMMON_COMMAND with callback
2021-05-12 09:06:03.382 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Sending data, type COMMON_COMMAND, payload 08
2021-05-12 09:06:03.383 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Sending raw data: 5500010005700838
2021-05-12 09:06:03.385 [DEBUG] [nternal.handler.EnOceanBridgeHandler] - set postmaster mailboxes
2021-05-12 09:06:03.386 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Enqueue new send request with ESP3 type SMART_ACK_COMMAND with callback
2021-05-12 09:06:03.387 [DEBUG] [nternal.handler.EnOceanBridgeHandler] - request version info
2021-05-12 09:06:03.388 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Enqueue new send request with ESP3 type COMMON_COMMAND with callback
2021-05-12 09:06:03.396 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2021-05-12 09:06:03.398 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 5 optional length 1 packet type 2
2021-05-12 09:06:03.399 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RESPONSE with code RET_OK payload 00FFF88480 received
2021-05-12 09:06:03.400 [DEBUG] [nternal.handler.EnOceanBridgeHandler] - received response for base id
2021-05-12 09:06:03.404 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:genericThing:160542a4f3:0589700D bridge status ONLINE
2021-05-12 09:06:03.413 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:genericThing:160542a4f3:058A42A4 bridge status ONLINE
2021-05-12 09:06:03.414 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Response handled
2021-05-12 09:06:03.530 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 92947108
2021-05-12 09:06:03.530 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 92893197
2021-05-12 09:06:03.636 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Sending data, type SMART_ACK_COMMAND, payload 0814
2021-05-12 09:06:03.637 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Sending raw data: 5500020006C40814C4
2021-05-12 09:06:03.646 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2021-05-12 09:06:03.647 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 1 optional length 0 packet type 2
2021-05-12 09:06:03.648 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RESPONSE with code RET_OK payload 00 received
2021-05-12 09:06:03.649 [DEBUG] [nternal.handler.EnOceanBridgeHandler] - received response for postmaster mailboxes
2021-05-12 09:06:03.649 [DEBUG] [nternal.handler.EnOceanBridgeHandler] - request learned smack clients
2021-05-12 09:06:03.651 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Enqueue new send request with ESP3 type SMART_ACK_COMMAND with callback
2021-05-12 09:06:03.651 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Response handled
2021-05-12 09:06:03.888 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Sending data, type COMMON_COMMAND, payload 03
2021-05-12 09:06:03.889 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Sending raw data: 5500010005700309
2021-05-12 09:06:03.906 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2021-05-12 09:06:03.921 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 33 optional length 0 packet type 2
2021-05-12 09:06:03.923 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RESPONSE with code RET_OK payload 00020F000002060900051AF109454F0103474154455741594354524C0000000000 received
2021-05-12 09:06:03.924 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Response handled
2021-05-12 09:06:04.140 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Sending data, type SMART_ACK_COMMAND, payload 06
2021-05-12 09:06:04.141 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Sending raw data: 5500010006790612
2021-05-12 09:06:04.152 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2021-05-12 09:06:04.160 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 1 optional length 0 packet type 2
2021-05-12 09:06:04.160 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RESPONSE with code RET_OK payload 00 received
2021-05-12 09:06:04.162 [DEBUG] [nternal.handler.EnOceanBridgeHandler] - received response for learned smack clients
2021-05-12 09:06:04.164 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Response handled
2021-05-12 09:07:13.637 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2021-05-12 09:07:13.639 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 14 optional length 7 packet type 1
2021-05-12 09:07:13.642 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RADIO_ERP1 with RORG VLD for 0589700D payload D201050000004F64820589700D0000FFFFFFFF5800 received
2021-05-12 09:07:13.648 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - ESP Packet payload D201050000004F64820589700D00 for 0589700D received
2021-05-12 09:07:15.991 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2021-05-12 09:07:15.993 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 14 optional length 7 packet type 1
2021-05-12 09:07:15.996 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RADIO_ERP1 with RORG VLD for 0589700D payload D201040000002464820589700D0000FFFFFFFF5200 received
2021-05-12 09:07:15.998 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - ESP Packet payload D201040000002464820589700D00 for 0589700D received
2021-05-12 09:09:05.971 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2021-05-12 09:09:05.973 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 14 optional length 7 packet type 1
2021-05-12 09:09:05.978 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RADIO_ERP1 with RORG VLD for 058A42A4 payload D20181000000646482058A42A40000FFFFFFFF4600 received
2021-05-12 09:09:05.979 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - ESP Packet payload D20181000000646482058A42A400 for 058A42A4 received

[DrRSatzteil]

OK... Correction: after a while the messages of 0589700D are triggering a transformation/item change as well. So maybe part of this is a timing problem after reboot. It seems that messages that are received to soon after booting up OH don't seem to be handled even though shown in the log