It seems there are 2 other devices on the network? Which one is the motion sensor - if it is the one you list above (0017880104b5e741), it seems to be working - or at least it is sending regular luminance sensor measurements.
Hi @chris,
This is why I said in a previous post that managing this in the dongle frame handler would simplifiy the transaction manager (if it has to handle this kind of situations)
I think it should do. I will try it to confirm, but I expect this to reduce the amount of errors. I also thought of this, but this is more a workaround than fixing the real issueā¦
I think I have found a race condition on the event notification (on the Telegesis mapping of SEQ numbers to transaction IDs). Please have a look at this piece of log (I have filtered the relevant lines):
2019-03-03 09:14:28.514 [DEBUG] [transaction.ZigBeeTransactionManager] - 14871/3: Sending ZigBeeTransaction [queueTime=7589, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 14871/3, cluster=0B04, TID=C7, identifiers=[1291]]]
2019-03-03 09:14:28.515 [DEBUG] [transaction.ZigBeeTransactionManager] - addTransactionListener: ZigBeeTransaction [queueTime=7590, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 14871/3, cluster=0B04, TID=C7, identifiers=[1291]]]
2019-03-03 09:14:28.517 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 10 outstanding
2019-03-03 09:14:28.518 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0/0 -> 14871/3, cluster=0B04, TID=C7, identifiers=[1291]]
2019-03-03 09:14:28.519 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=199, commandId=0]
2019-03-03 09:14:28.520 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=14871/3, profile=0104, cluster=0B04, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=F9, payload=00 C7 00 0B 05]
2019-03-03 09:14:28.522 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=14871, sourceEp=0, destEp=3, profileId=260, clusterId=2820, messageData=00 C7 00 0B 05, messageId=null]
2019-03-03 09:14:28.524 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSendUnicastCommand [address=14871, sourceEp=0, destEp=3, profileId=260, clusterId=2820, messageData=00 C7 00 0B 05, messageId=null]
2019-03-03 09:14:28.527 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data:AT+SENDUCASTB:05,3A17,00,03,0104,0B04^M^@Ć^@^K^E
2019-03-03 09:14:28.770 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SEQ:85
2019-03-03 09:14:28.771 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:OK
2019-03-03 09:14:28.777 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C7 state=TX_ACK
2019-03-03 09:14:28.783 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:ACK:85
2019-03-03 09:14:28.786 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID C7 TX_ACK -> 10
2019-03-03 09:14:28.786 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisAckMessageEvent [messageId=133]
2019-03-03 09:14:28.787 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - No sequence correlated for ACK messageId 133
2019-03-03 09:14:28.789 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID C7 -> TX_ACK == TRANSMITTED
2019-03-03 09:14:28.800 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:3A17,0104,00,03,0B04,09:^XĆ^A^K^E^@)`m,-58,FF
2019-03-03 09:14:28.802 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=14871, profileId=260, destinationEp=0, sourceEp=3, clusterId=2820, messageData=18 C7 01 0B 05 00 29 60 6D, rssi=-88, lqi=255]
2019-03-03 09:14:28.804 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=14871/3, destinationAddress=0/0, profile=0104, cluster=0B04, addressMode=null,radius=0, apsSecurity=false, apsCounter=00, payload=18 C7 01 0B 05 00 29 60 6D]
2019-03-03 09:14:28.805 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=199, commandId=1]
2019-03-03 09:14:28.807 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Electrical Measurement: 14871/3 -> 0/0, cluster=0B04, TID=C7, records=[ReadAttributeStatusRecord [attributeDataType=SIGNED_16_BIT_INTEGER, attributeIdentifier=1291, status=SUCCESS, attributeValue=28000]]]
2019-03-03 09:14:28.828 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Electrical Measurement: 14871/3 -> 0/0, cluster=0B04, TID=C7, records=[ReadAttributeStatusRecord [attributeDataType=SIGNED_16_BIT_INTEGER, attributeIdentifier=1291, status=SUCCESS, attributeValue=28000]]] ZigBeeTransaction [queueTime=7903, state=TRANSMITTED, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 14871/3, cluster=0B04, TID=C7, identifiers=[1291]]]
2019-03-03 09:14:28.830 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction response received - waiting TX_ACK: ZigBeeTransaction [queueTime=7905, state=RESPONDED, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 14871/3, cluster=0B04, TID=C7, identifiers=[1291]]]
...
2019-03-03 09:14:36.789 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [queueTime=15864, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 14871/3, cluster=0B04, TID=C7, identifiers=[1291]]]
2019-03-03 09:14:36.792 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionComplete: ZigBeeTransaction [queueTime=15867, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 14871/3, cluster=0B04, TID=C7, identifiers=[1291]]] FAILED
2019-03-03 09:14:36.794 [DEBUG] [transaction.ZigBeeTransactionManager] - removeTransactionListener: ZigBeeTransaction [queueTime=15869, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 14871/3, cluster=0B04, TID=C7, identifiers=[1291]]]
- As getting the SEQ number is handled on a separate worker thread, the ACK may arrive too fast and be processed before the āmessageIdMapā is updated by the worker thread.
- We get a āNo sequence correlated for ACK messageIdā log entry @2019-03-03 09:14:28.787, hence the RX_ACK is never notified
- Later the transaction gets a response from the remote device @2019-03-03 09:14:28.800
- The transaction is matched, but it gets āwaiting TX_ACKā @2019-03-03 09:14:28.830 (BTW, should not it be āwaiting RX_ACKā in the log entry?)
- The RX_ACK never arrives, as it was discarded before (by not having a SEQ mapping yet when it arrived)
- The transaction is eventually cancelled (timed out).
One note here: I see that if we receive a NACK, but we received a response, we complete the transaction instead of cancelling it (which makes sense). Shouldnāt we do the same if it times out?
On the race condition itself, maybe this might be fixed by making SEQ/ACK/NACK reponses being processed in sequence (this should not be an issue, as the SEQ/OK/ERROR responses should come āimmediatelyā (few ms) after commands are sent, so no real waiting here:
- Make āZigBeeDongleTelegesis.commandSchedulerā a FixedThreadPool of size 1 instead of a CachedThreadPool (we can only have one command waiting for SEQ/OK/ERROR, so it should never go over 1 thread waiting for TX_ACK anyway)
- In ZigBeeDongleTelegesis.telegesisEventReceived() handle the TelegesisAckMessageEvent and TelegesisNackMessageEvent on an runnable in ācommandSchedulerā instead of in the same thread.
This still leaves the door open to receiving and notifying the command response itself before the TX_ACK is processed, so maybe it would be even safer to process the whole āZigBeeDongleTelegesis.telegesisEventReceived()ā block on the worker thread. This would make all received commands from the dongle go into a āpipelineā, but I understand there is no blocking there except of waitng for TX_ACK/NAK, so it may make sense.
What do you think?
Pedro
Sure, but as discussed afterwards, that implies secondary queuing in the dongle, and that is a bad idea for the reasons stated previously. The transaction manager should manage the transactions as much as possible - secondary queuing will cause problems and should be avoided other than to cope with protocol level delays.
In any case, even if it was done in the dongle, there would still be the same issue - weād need to account for cases that could cause the counter to get out of sync somehow.
True, but I donāt have a big issue with that - so long as itās not adversely impacting overall system performance (too much anyway). We need to try and tune the manager so that the system works well - as mentioned earlier - it doesnāt necessarily need to be tuned exactly to the constraints of each dongle (although that could be possible if needed).
Let me know if this works without too much impact.
Yes - I missed the timeout and Iāll update - thanks.
I think it all makes sense and I like your idea of using the schedule to ensure processing through the āpipelineā.
Have you tested this? My question really is - do you have the source such that you could make a PR against the transaction-queue branch? If so, that would be appreciated - otherwise I will take a look at this later today.
My goal is to get this merged today or tomorrow if possible - Iām sure there will be more enhancements etc that can be done, but I think itās working pretty well so it would be good to get it into the wider community 
.
Thanks (again).
I can test this today. I may need some guidance though on how to PR against a branch, as I have always done against āmasterā.
Pedro
Hi @cris,
Done
This PR does:
- Changes max outstanding transactions from 10 to 9
- Makes all responses from the telegesis dongle be processed in order (as discussed above)
My network has started no with no TOO_MUCH_UNICAST errors, and no correlation errors (and cancelled transactions) for unmatched transaction IDs (I had several in the previous run).
Thanks @puzzle-star - I will take a look shortly and create a new snapshot for anyone testing this branch.
FYI Iāve just pushed a binding branch with the updated DataStore. I now have a branch of the library for 1.2.0 which includes all the upcoming breaking changesā¦ I hope to get these all merged over the next month.
Oddly, the Hue binding works in such a way where the Hue motion sensor shows up as three separate āThingsā, a motion sensor thing, a light sensor thing and a temperature sensor thing. I believe the Hue motion sensor and remote dimmer switch were fairly recently added to the Hue binding. All three āThingsā also seem to have overlapping channels such as battery level. Seems kind of weird but is only one actual physical device
I have sent a new PR (this one against master) to remove the synchronized blocks from the updateNode / addNode / removeNode which still had a call to network serialization inside.
I know this will probably be changed in 1.2.0 with the datastore, but in 1.1.11 transaction-queue, and if we put in a pipeline the processing of commands from the dongle, this might affect at some moment.
I have not seen any error / Timeout on the dongle due to this now, as we have incremented the timeout and in a previous PR we avoided serveral writes in parallel to the xml file, but no point in blocking the pipeline for 2-3 secs if not needed.
Pedro
There is only the one physical END_DEVICE on the system. What about the exception that occurred here:
2019-03-02 10:50:00.333 [ERROR][ool-24-thread-4][iscovery.ZigBeeNodeServiceDiscoverer] - 0017880104B5E741: Node SVC Discovery: exception:
As I said above,
I canāt see how that is possible. There are two different EUIs in the log so there really must be two different devices. If you have a motion sensor, and a remote dimmer - isnāt that two devices?
Iām sorry Chris, I own a Hue motion sensor and a Hue dimmer but the logs posted above are not my logs. Sorry for the misunderstanding. I was just explaining that on my system, my Hue motion sensor shows up as three separate āthingsā
Is this in the Hue binding, or the ZigBee binding? Iām not sure how the ZigBee binding could do this, and Iāve no real idea what the Hue binding does.
I see two EUI addresses - maybe one is the coordinator - itās a bit hard to tell in this log.
This isnāt an issue - itās a problem during binding shutdown (Iāll take a look at it, but as itās during shutdown, itās not going to be a problem here).
Ok, but I can see it is reporting, so Iām not sure what is happening. It looks ok from what I can see.
The Hue motion sensor has EUI address 0017880104B5E741 and the CC2531 coordinator has the EUI address 00124B0009EB08E0.
This is caused by the scheduler not accepting any further requests as it is being shutdown, and something in the system sent it a request. It rejected the request, and the binding shut down normally.
The logging is a pain, but ultimately itās not an issue.
Hi @chris,
Looks like my home is a good test lab for error cases 
I have come across two bursts of TOO_MANY_UNICAST errors in my log. It seems that reducing by 1 the max outstanding transactions is not enough. (See the log extract below, again filtered for the relevant parts, for the first burst).
There are two concurrent transactions where the APS NACK comes about 25 seconds after TX_ACK (SEQ number), so the transaction is cancelled before.
This ~25 seconds delay is consistent accross the instances of this issue when I see it on the logs. The specific device being addressed in the log below is a IKEA remote controller (sleepy) and it is very near the dongle.
So this error is probably common enough to deserve attentionā¦ Three solutions I can think of:
- Reduce max outstading transactions to 8 (but it does not guarrantee we wonāt find three transactions failing like this)
- Increase the transaction timeout to 30s. This may make sense in the end if we are waiting for a APS ACK/NAK and it can be retried that long by the dongleā¦ and then bring back max outstanding transactions to 10 as then it would not be necessary to decrease it.
- Keep track of TX_ACK vs RX_ACK/NACK on the transaction manager (but this complicates handling of completed transactions, as we still need to listen for cancelled ones)
What do you think? I would increase the timeout to 30ā¦
2019-03-03 14:05:05.946 [DEBUG] [transaction.ZigBeeTransactionManager] - 47390/0: Sending ZigBeeTransaction [queueTime=5634, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 47390/0, cluster=0021, TID=14, srcAddress=000B57FFFE9BE6EC, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F001113A331, dstEndpoint=1]]
2019-03-03 14:05:05.947 [DEBUG] [transaction.ZigBeeTransactionManager] - addTransactionListener: ZigBeeTransaction [queueTime=5636, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 47390/0, cluster=0021, TID=14, srcAddress=000B57FFFE9BE6EC, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F001113A331, dstEndpoint=1]]
2019-03-03 14:05:05.949 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 9 outstanding
2019-03-03 14:05:05.950 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0/0 -> 47390/0, cluster=0021, TID=14, srcAddress=000B57FFFE9BE6EC, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F001113A331, dstEndpoint=1]
2019-03-03 14:05:05.953 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=47390/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=14, payload=00 EC E6 9B FE FF 57 0B 00 01 01 00 03 31 A3 13 11 00 6F 0D 00 01]
2019-03-03 14:05:05.955 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=47390, sourceEp=0, destEp=0, profileId=0, clusterId=33, messageData=00 EC E6 9B FE FF 57 0B 00 01 01 00 03 31 A3 13 11 00 6F 0D 00 01, messageId=null]
...
2019-03-03 14:05:06.546 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSendUnicastCommand [address=47390, sourceEp=0, destEp=0, profileId=0, clusterId=33, messageData=00 EC E6 9B FE FF 57 0B 00 01 01 00 03 31 A3 13 11 00 6F 0D 00 01, messageId=null]
2019-03-03 14:05:06.550 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data:AT+SENDUCASTB:16,B91E,00,00,0000,0021^M^@ƬƦ<U+009B>Ć¾ĆæW^K^@^A^A^@^C1Ā£^S^Q^@o^M^@^A
2019-03-03 14:05:06.829 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SEQ:F3
2019-03-03 14:05:06.831 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:OK
2019-03-03 14:05:06.836 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=14 state=TX_ACK
2019-03-03 14:05:06.837 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=14, state=TX_ACK, outstanding=9
2019-03-03 14:05:06.839 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 14 -> TX_ACK == TRANSMITTED
...
2019-03-03 14:05:14.839 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=14528, state=FAILED, sendCnt=1, command=BindRequest [0/0 -> 47390/0, cluster=0021, TID=14, srcAddress=000B57FFFE9BE6EC, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F001113A331, dstEndpoint=1]]
2019-03-03 14:05:14.841 [DEBUG] [transaction.ZigBeeTransactionManager] - removeTransactionListener: ZigBeeTransaction [queueTime=14530, state=FAILED, sendCnt=1, command=BindRequest [0/0 -> 47390/0, cluster=0021, TID=14, srcAddress=000B57FFFE9BE6EC, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F001113A331, dstEndpoint=1]]
2019-03-03 14:05:14.843 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 8 outstanding
2019-03-03 14:05:14.843 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000B57FFFE9BE6EC: transactionComplete FAILED 0
2019-03-03 14:05:14.845 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000B57FFFE9BE6EC: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=14533, state=WAITING, sendCnt=1, command=BindRequest [0/0 -> 47390/0, cluster=0021, TID=14, srcAddress=000B57FFFE9BE6EC, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F001113A331, dstEndpoint=1]]
...
2019-03-03 14:05:20.424 [DEBUG] [transaction.ZigBeeTransactionManager] - 47390/0: Sending ZigBeeTransaction [queueTime=20112, state=WAITING, sendCnt=1, command=BindRequest [0/0 -> 47390/0, cluster=0021, TID=14, srcAddress=000B57FFFE9BE6EC, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F001113A331, dstEndpoint=1]]
2019-03-03 14:05:20.425 [DEBUG] [transaction.ZigBeeTransactionManager] - addTransactionListener: ZigBeeTransaction [queueTime=20114, state=WAITING, sendCnt=1, command=BindRequest [0/0 -> 47390/0, cluster=0021, TID=14, srcAddress=000B57FFFE9BE6EC, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F001113A331, dstEndpoint=1]]
2019-03-03 14:05:20.444 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 9 outstanding
2019-03-03 14:05:20.445 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0/0 -> 47390/0, cluster=0021, TID=14, srcAddress=000B57FFFE9BE6EC, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F001113A331, dstEndpoint=1]
2019-03-03 14:05:20.446 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=47390/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=38, payload=00 EC E6 9B FE FF 57 0B 00 01 01 00 03 31 A3 13 11 00 6F 0D 00 01]
2019-03-03 14:05:20.447 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=47390, sourceEp=0, destEp=0, profileId=0, clusterId=33, messageData=00 EC E6 9B FE FF 57 0B 00 01 01 00 03 31 A3 13 11 00 6F 0D 00 01, messageId=null]
...
2019-03-03 14:05:20.748 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSendUnicastCommand [address=47390, sourceEp=0, destEp=0, profileId=0, clusterId=33, messageData=00 EC E6 9B FE FF 57 0B 00 01 01 00 03 31 A3 13 11 00 6F 0D 00 01, messageId=null]
2019-03-03 14:05:20.751 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data:AT+SENDUCASTB:16,B91E,00,00,0000,0021^M^@ƬƦ<U+009B>Ć¾ĆæW^K^@^A^A^@^C1Ā£^S^Q^@o^M^@^A
2019-03-03 14:05:20.894 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SEQ:17
2019-03-03 14:05:20.896 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:OK
2019-03-03 14:05:20.898 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=14 state=TX_ACK
2019-03-03 14:05:20.899 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=14, state=TX_ACK, outstanding=9
2019-03-03 14:05:20.900 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 14 -> TX_ACK == TRANSMITTED
...
2019-03-03 14:05:28.901 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=28589, state=FAILED, sendCnt=2, command=BindRequest [0/0 -> 47390/0, cluster=0021, TID=14, srcAddress=000B57FFFE9BE6EC, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F001113A331, dstEndpoint=1]]
2019-03-03 14:05:28.903 [DEBUG] [transaction.ZigBeeTransactionManager] - removeTransactionListener: ZigBeeTransaction [queueTime=28591, state=FAILED, sendCnt=2, command=BindRequest [0/0 -> 47390/0, cluster=0021, TID=14, srcAddress=000B57FFFE9BE6EC, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F001113A331, dstEndpoint=1]]
2019-03-03 14:05:28.904 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 8 outstanding
2019-03-03 14:05:28.904 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000B57FFFE9BE6EC: transactionComplete FAILED 0
2019-03-03 14:05:28.905 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000B57FFFE9BE6EC: transactionComplete exceeded retries 2
2019-03-03 14:05:28.907 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=28595, state=FAILED, sendCnt=2, command=BindRequest [0/0 -> 47390/0, cluster=0021, TID=14, srcAddress=000B57FFFE9BE6EC, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F001113A331, dstEndpoint=1]]
...
2019-03-03 14:05:33.459 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisSendUnicastCommand [address=49600, sourceEp=0, destEp=0, profileId=0, clusterId=33, messageData=00 CE AC 32 FE FF 57 0B 00 01 06 00 03 31 A3 13 11 00 6F 0D 00 01, messageId=null, status=TOO_MANY_UNICAST]
2019-03-03 14:05:33.624 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisSendUnicastCommand [address=49600, sourceEp=0, destEp=0, profileId=0, clusterId=33, messageData=00 CE AC 32 FE FF 57 0B 00 01 06 00 03 31 A3 13 11 00 6F 0D 00 01, messageId=null, status=TOO_MANY_UNICAST]
2019-03-03 14:05:33.886 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisSendUnicastCommand [address=60305, sourceEp=0, destEp=0, profileId=0, clusterId=33, messageData=00 62 A6 B1 00 AA 3E B0 7C 03 04 0B 03 31 A3 13 11 00 6F 0D 00 01, messageId=null, status=TOO_MANY_UNICAST]
...
2019-03-03 14:05:33.887 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:NACK:F3
...
2019-03-03 14:05:48.258 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:NACK:17
Pedro
@chris I just installed the latest snapshot. Except the Trust sensor is having problems again, I see a very odd situationā¦
My Hue Dimmer Switch was somekind rediscovered. (it was in my inbox, and showing lots of new channels). I just added it from the inboxā¦ But then I end up with the same Dimmer Switch, twice.
Notice the two Philips RWL021ā¦ TheyĀ“ve godt the same ID.
Even more strangeā¦ the āoldā still work. I have not linked any of the channels for the ānewā discovery Dimmer Switch, as I wanted to show this to you first.
They have different UIDs though - Iām not really sure how thatās possible. Do you have a log? Iām assuming youāre not using static thing definitions and somehow creating different thing UIDs?
Hi @Kim_Andersen,
I think this is an issue with statically defined devices (I am also seeing this with mine). When discovery is started, it goes into the inbox as the device of type āzigbee:device:ā with that serial does not exist. After some seconds, the discovery process determines it is a āzigbee:philips_rwl021:ā, and removes the previous one from the inbox.
If you accept the device from the inbox in the interim, it gets duplicated.
@chris, does this make sense? I planned to look into this (in the binding, not ZSS) after the transaction manager is merged. It would be easier to solve if the extended callback allowing the binding to query the existing items had not been deprecated, thoughā¦
Pedro
Yeah I have a debug logā¦
I started to update the binding using 5ivers script at around 16:32 today.
zigbee.rar.txt (189.7 KB)
I let PaperUI/binding discover all things automaticly. I only link the items manually.