Zigbee binding

puzzle-star · February 25, 2019, 6:26am

Good one

I will try the changes to the updated branch later today or tomorrow, but it looks good.

BTW, I have already identified two different sources for the TOO_MANY_UNICAST errors I still see. None are “due to the code”, but more related to Telegesis indeed:

Surprisingly enough (at least for me) the ACK message is being reported / processed by the dongle sometimes after the command response arrives from the remote device: the transaction manager (correctly) assumes the transaction is finished and sends a new one, but the dongle has not still processed the ACK, and still considers the transaction “On Air”, so it responds with Error 72.
I have seen some NACKs from the dongle arriving more than 20 seconds after the TX SEQ/OK. Of course, the transaction is cancelled much before, so the transaction manager is again sending a new transaction when then cancelled one is not finished from the dongle point of view.

But should these “error cases” be treated on the transaction manager, or in the dongle code itself?

Pedro

chris · February 25, 2019, 8:35am

Thanks Pedro. It would be great if you could comment on github once you’ve had a test - either positive or negative

Interesting…

It may depend - however in these cases, I’m not sure the dongle has all the information to allow it to process these cases does it?..

For the first one - can you provide a log? I was trying to avoid the situation where we require a strict progress of all the stages, so the manager will complete the transaction if it receives the response. Maybe we also need an option to also wait for the ACK? I was trying to avoid this as it allowed the situation where the dongles may, or may not, provide the status updates (for example, the CC2531 code doesn’t do this).

For the second one, it probably should be handled by increasing the timer in the transaction manager. Maybe we need a TransactionManagerProfile that allows a single class for tuning the manager (similar to the QueueProfile for tuning the queue). This could be configured on a per dongle basis (or any other basis).

I’m happy to hear your thoughts .

TheNetStriker · February 26, 2019, 7:52pm

Does anyone also uses the CEL Meshconnect EM3588 usb stick on a Raspberry Pi 3? I’am currently using the stick with 115200 baud and hardware flow control and I’m getting a lot of those errors in the kernel log:

Feb 24 17:52:49 OpenHabian01 kernel: [460362.246691] cp210x ttyUSB0: failed get req 0x8 size 1 status: -71
Feb 24 17:53:01 OpenHabian01 kernel: [460373.746561] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:53:01 OpenHabian01 kernel: [460373.751707] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:53:09 OpenHabian01 kernel: [460381.755882] cp210x ttyUSB0: failed get req 0x8 size 1 status: -71
Feb 24 17:53:16 OpenHabian01 kernel: [460388.749564] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:53:16 OpenHabian01 kernel: [460388.754189] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:53:31 OpenHabian01 kernel: [460403.752323] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:53:31 OpenHabian01 kernel: [460403.756216] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:53:46 OpenHabian01 kernel: [460418.755224] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:53:46 OpenHabian01 kernel: [460418.758738] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:53:58 OpenHabian01 kernel: [460430.825823] cp210x ttyUSB0: failed get req 0x8 size 1 status: -71
Feb 24 17:54:01 OpenHabian01 kernel: [460433.758704] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:54:01 OpenHabian01 kernel: [460433.763189] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:54:16 OpenHabian01 kernel: [460448.766236] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:54:16 OpenHabian01 kernel: [460448.768180] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:54:31 OpenHabian01 kernel: [460463.769076] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:54:31 OpenHabian01 kernel: [460463.770927] cp210x ttyUSB0: failed set request 0x7 status: -32
Feb 24 17:54:33 OpenHabian01 kernel: [460466.017352] cp210x ttyUSB0: failed get req 0x8 size 1 status: -71

If anyone has the same setup, could you please check your kernel logs if you also have those errors?

chris · February 27, 2019, 7:14pm

I’ve deployed a new version of 1.1.11-SNAPSHOT with the latest transaction manager. If there are no further issues I will look to merge this in the coming days.

5iver · February 27, 2019, 8:35pm

I updated, and lost all control of my devices. Restart of OH did not help. Everything appears to be online. No time to troubleshoot ATM, but will in a couple hours.

Lots of errors in log (wasn’t in debug yet)… here is an example.

2019-02-27 15:26:11.093 [ERROR] [com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] - 7CE524000011AAA3: Node SVC Discovery: exception: 
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@40fac25e rejected from java.util.concurrent.ScheduledThreadPoolExecutor@4d66e69a[Shutting down, pool size = 6, active threads = 6, queued tasks = 0, completed tasks = 181]
	at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(ScheduledThreadPoolExecutor.java:326) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor.schedule(ScheduledThreadPoolExecutor.java:533) ~[?:?]
	at com.zsmartsystems.zigbee.ZigBeeNetworkManager.rescheduleTask(ZigBeeNetworkManager.java:585) ~[362:com.zsmartsystems.zigbee:1.1.11.SNAPSHOT]
	at com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer$NodeServiceDiscoveryTask.run(ZigBeeNodeServiceDiscoverer.java:646) [362:com.zsmartsystems.zigbee:1.1.11.SNAPSHOT]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
2019-02-27 15:27:42.668 [ERROR] [com.zsmartsystems.zigbee.app.discovery.ZigBeeNetworkDiscoverer] - 0: NWK Discovery error during node discovery: 
java.lang.NullPointerException: null
	at com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp.sendCommand(ZigBeeDongleEzsp.java:564) ~[?:?]
	at com.zsmartsystems.zigbee.ZigBeeNetworkManager.sendCommand(ZigBeeNetworkManager.java:703) ~[362:com.zsmartsystems.zigbee:1.1.11.SNAPSHOT]
	at com.zsmartsystems.zigbee.transaction.ZigBeeTransactionManager.send(ZigBeeTransactionManager.java:436) ~[362:com.zsmartsystems.zigbee:1.1.11.SNAPSHOT]
	at com.zsmartsystems.zigbee.transaction.ZigBeeTransactionManager.sendNextTransaction(ZigBeeTransactionManager.java:660) ~[362:com.zsmartsystems.zigbee:1.1.11.SNAPSHOT]
	at com.zsmartsystems.zigbee.transaction.ZigBeeTransactionManager.queueTransaction(ZigBeeTransactionManager.java:365) ~[362:com.zsmartsystems.zigbee:1.1.11.SNAPSHOT]
	at com.zsmartsystems.zigbee.transaction.ZigBeeTransactionManager.sendTransaction(ZigBeeTransactionManager.java:349) ~[362:com.zsmartsystems.zigbee:1.1.11.SNAPSHOT]
	at com.zsmartsystems.zigbee.ZigBeeNetworkManager.sendTransaction(ZigBeeNetworkManager.java:1460) ~[362:com.zsmartsystems.zigbee:1.1.11.SNAPSHOT]
	at com.zsmartsystems.zigbee.app.discovery.ZigBeeNetworkDiscoverer.getIeeeAddress(ZigBeeNetworkDiscoverer.java:351) ~[362:com.zsmartsystems.zigbee:1.1.11.SNAPSHOT]
	at com.zsmartsystems.zigbee.app.discovery.ZigBeeNetworkDiscoverer.access$600(ZigBeeNetworkDiscoverer.java:49) ~[362:com.zsmartsystems.zigbee:1.1.11.SNAPSHOT]
	at com.zsmartsystems.zigbee.app.discovery.ZigBeeNetworkDiscoverer$2.run(ZigBeeNetworkDiscoverer.java:308) [362:com.zsmartsystems.zigbee:1.1.11.SNAPSHOT]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]

chris · February 27, 2019, 8:47pm

Is this during the binding shutdown rather than the new binding startup?

I’m not seeing this here - when you get a chance a debug log would be great…

Thanks Scott.

5iver · February 27, 2019, 9:37pm

OK… had a tree fall over the driveway, and had to cut it up to go pickup daughter from Engineering Club!

It seems that this was just that all bulbs dropped from the network after the upgrade. Power cycle and discovery is bringing them back. Not sure if this is an issue, or if you’d like to investigate further (might be repeatable).

chris · February 27, 2019, 9:40pm

If it’s repeatable, then fire me over a debug log - the changes since the last version are not very extensive so I don’t really expect issues (but… ).

puzzle-star · February 28, 2019, 7:10pm

Hi @chris,

Sorry for not having answered yet to this. It has been a busy week… at the same time as the MWC, that is time consuming on its own

I have tested the transaction-queue branch as it is today, and it is working fine for me. Still with some TOO_MANY_UNICAST errors as per my previous comment (as expected), but even with these errors the whole system is working much better with the transaction manager than without it (and anyway these errors would be also happening, and much more indeed, without the transaction manager).

I will provide same feedback on github.

Yes, I will prepare it and send it (but probably not today…)

To make sure this was happening (and not just some weird ordering in the log), I implemeted a fix on this assumption:

If a transaction is matched before the ACK is received, I put an entry in the log and store the received command, but skip completing the transaction
When and ACK is received and there is a stored received command for the transaction, the transaction is completed and logged.

As you say, this only works on the Telegesis, and makes the other dongles not working, as they do not enforce going through ACK. I just did it for testing, and the logs I will provide you are including this, so you will see some entries like “transaction matched before being acked” and “completing acked transaction” on this log.

Well, I see this more an error from the dongle (and not happening too much, but it is reproducible anyway). According to the dongle config register I think manages the MAC timeout (I checked in case it had a non default value for some reason), NACK should be sent after 7 seconds, while I saw it being sent more than 20 seconds after the corresponding SEQ, and the dongle was not blocked, as many commands and transactions went through correctly in this period.

It if is some temporary error or overload in the dongle, I think the solution would not be rising the timeout (30secs may be too much), but maybe the best way to handle this comes in the answer below.

Ideally, the transaction manager should handle all sort of “constraints”, but every dongle has different ones, so trying to make the transaction manager being able to manage all these situations may complicate it too much:

The Telegesis sends ACKS/NACKS, the others don’t
The Telegesis accepts 10 on air unicasts and 3 broadcasts in 8 seconds, while the transaction manager accounts for all these together in outstandingTransactions
The transaction manager considers a transaction completed when an answer is received, the telegesis when a ACK/NACK is reported.
Other dongles may have a totally different set of “formulas”.

I think (but this is arguable ), that the TransactionManagerProfile is a good thing (and needed), to configure such things, but it cannot accout for all present and future possibilities.

I would, anyway, suggest that we need to make the transaction manager discount broadcasts and multicasts from the outstanding transactions counter, at least as a configurable option in the profile (sorry to complicate things )

Also, I think the dongle has the information for it not to fail: even if we do not enforce all stages (so we complete transactions without the ack), or we allow for more outstandingTransactions in the transaction manager than the dongle may accept (due to an errror condition as above, or because we decide to do so because we know the dongle can consider its transaction finished on ACK, before receiveing the response, leaving room for a new transaction).

Each dongle frame handler should know very easliy if it is ready to send new transactions (i.e telegesis code can count concurrent live unicasts very easily), and if it is not ready, keep the pending ones in its queue till it is ready instead of sending without checking.

This would simplify a bit the transaction manager handling of possible error conditions in the dongle (errors, timeouts, etc), and I think is indeed a good thing, as the transaction manager can have outstanding transactions that from the dongle perspesctive are finished.

Sorry for the long “dissertation”…

Pedro

chris · February 28, 2019, 9:31pm

Thanks @puzzle-star - I appreciate the feedback and I’ll take a better look at these issues over the coming days.

That’s not 100% correct - the Ember also supports this. The Ember dongle is used extensively (not just in OH, but other systems as well use large quantities).

Not really - they should implement the same thing. The sending of the transaction status was designed to be optional, and I’ve only implemented it for Telegesis and Ember, but if implemented, it should be implemented in this common way.

Probably you are right, but there should be a standard way to do things, and a standard set of assumptions in the manager, that dongles need to respect. If they don’t do it natively, then the driver needs to fix it.

In this case, maybe we need to handle this out of order reception. I would guess that the ACK comes from the APS ACK, so it is always possible that this can come after the response if there is a lost frame (and maybe even if no lost frames) at the APS layer.

Sorry - I’m not sure what you mean by this?

True - but I think we should try and avoid queuing in the dongle any more than is needed as this will screw up the timers in the transaction manager. So long as it’s quick, it won’t matter too much, but buffering in the transaction manager is better as it won’t start the timers until the frame is sent to the dongle.

No problem - as I said - I will spend some more time to digest it over the weekend.

I appreciate your testing and feedback on this - thanks.

chris · March 2, 2019, 11:01am

Is your point here that it doesn’t differentiate between broadcasts and unicasts? If so, it does to an extent. The broadcast queue will only release a certain number of transactions per period - or to be more precise, it will only allow transactions to be released at a set spacing. I know this isn’t exactly the same, but if we set the spacing here to 2.7 seconds, then it will ensure that there are only ever 3 broadcasts outstanding at once, thus respecting the constraints above.

This could be changed in future to have a maxOutstanding per queue, this allowing the situation where we send 3 broadcasts immediately and then none for the remainder of the 8 seconds.

However, we also need to think about what the network can do - even if the dongle can send 3 broadcasts in 8 seconds, most routers will not handle this, or at least they will not handle this with end devices. The standard only requires a router to buffer a single frame per end device, and to store this for the standard 7.6 seconds, so sending more broadcasts will in any case cause some loss at this level and therefore may not be a good idea within the system.

I’ve now changed this. I’ve added a RESPONDED state - if the application response is received before the ACK/NAK, then we enter the RESPONDED state until the ACK/NAK is received, then the transaction is completed. This logic is only applied if we received the TX_ACK earlier, so it’s not applied for dongles that don’t provide this feedback (ie the CC2531).

Hopefully not “totally different”, but for sure the number of outstanding transactions may be different. The question is if we need to handle that - I think at the moment we don’t as both Ember and Telegesis should allow 10 transactions outstanding (although compile time options can change this in the Ember, so it’s possible that some implementations may be different).

I think I will keep this as a next step for now and see how things look once this is all merged.

I will need to think about this some more. It might be useful as a second order improvement when the network is really busy, but as broadcasts aren’t used too often (other than system start) it might just be safer to leave as is.

Let’s store this for now.

This error condition should now not exist.

As mentioned earlier, I’m not too keen to have more queueing in the dongle handler than is absolutely necessary. We should try and cover most common scenarios in the transaction manager where the system implications of queues and delays can (hopefully ) be properly managed.

I don’t know what you refer to here? The transaction manager can only handle error conditions that are passed back from the dongle, and this is only the transaction states. I’m not sure what you are suggesting should be simplified?

Thanks again for the review and design challenges .

puzzle-star · March 2, 2019, 1:20pm

Hi @chris,

Yes, but not exactly in the same manner you describe. The issue I find is that, i.e., Telegesis can handle 10 concurrent unicasts + 3 broadcasts in 8 seconds.

outstandingTransactions does not differenciate. If we have 7 unicasts + 3 broadcasts on air, the transaction manager will not send any more unicasts, while it could still send three.

I think this is what you mean by later differenciating maxOutstanding per queue, am I right?

So it “learns” from the dongle… Nice

Well, I meant “a bit more” different than just the number of transactions. I do not know about all the dongles (and what might come), but coming back to the Telegesis dongle it counts separately, and in a different way, the unicasts (10 concurrently) from the broadcasts (3 in 8 seconds). Maybe other dongles could have the constraint on the overall count (unicast + broadcast concurrently), etc? This is what I meant by “totally different set of formulas” for different dongles.

I agree this can come as a later improvement, but still think it would be necessary

The responded status surely fixes the response arriving before the ACK/NACK. More than an error condition, I would name it a behaviour from the dongle I did not expect.

But the second issue I found, a NACK arriving >20s after the SEQ, is probably an error condition from the dongle that the transaction manager may not handle properly.

The transaction will be cancelled due to a timeout, so the transaction manager will send a new transaction to the dongle, but the dongle is not really ready, because it still considers the transaction on air (till it sends the NACK). Rising the transaction timeout to a larger time may prevent this, but is it reasonable to increase this timeout that much? 30s? (or 60, or 90?) I would not try to solve this at the transaction manager, as this is an error in the dongle.

Yes, and it will properly cancel a timed out transaction. The problem is the one I describe above. How do we handle this on the transaction manager?

The problem of a transaction failing like this is not the sole transaction, but that then several other in a row are sent (and errored) during several seconds. Once the transaction times out (no NAK received yet):

As there is a “free” transaction, the transaction manager sends a new one.
It receives immediately an error (due to TOO_MANY_UNICAST)
As again it has another free transaction, it sends a new one…
And so on for several seconds, till the NAK (or even maybe an ACK) for the cancelled transaction is received.

I agree, but would it then make sense to listen at the transaction state progress changes (not only failed, completed, etc) on the transaction manager, and count RX_ACKed/NACKed transactions vs TX_ACKed ones, so that we never exceed a given limit? This is very specific for every dongle, should not this be better handled in the dongle frame handler itself?

Pedro

chris · March 2, 2019, 1:44pm

Correct.

Ok, and I agree, but as I also said, maybe at system level these aren’t “good” anyway. For example, routers will only hold a single broadcast, and a single frame for their children, and only for the 8 second period. So, sending 3 broadcasts at once might actually be a bad idea anyway. Therefore, we shouldn’t (necessarily) set these constraints based on what the dongle allows, but instead what the system needs.

I do agree your point though - but I think that (probably) we can handle different dongles with a general set of constraints so that the system works well for different devices. Of course, maybe one day there will be something that is quite different, but we’ll deal with the then

Let’s see - I think that we an deal with this in a common way, but I might be wrong. We don’t have to optimise the network for every dongle as at system level, it may not really matter. Let’s see though - I’m not against this (otherwise I wouldn’t have suggested it in the first place ).

Agreed - I’m not really sure how to handle this one at the moment. I don’t think it’s possible to cancel a transaction in the dongle once it’s been sent, so we just have to wait I think?

I’m not sure - I can’t see any real way to do this. I agree it’s not sensible to extend the timer too much.

Yep - I agree, but again, I’m not sure how we can handle this. The “correct” way would probably be to send a command to the dongle to cancel the transaction when the transaction manager gives up, however I don’t think that either the Telegesis, or the Ember dongles support this.

Maybe this is possible - if I understand your point, we would effectively have a dynamic “maxOutstandingTransactions” based on this, however I think we then start to add more complexity as we need to then deal with error cases to make sure the counters don’t get out of sync and we slowly loose the ability to send transactions.

We could probably also cover this corner case by making the maximum number of transactions 9 instead of 10 - I know this doesn’t cover the possibility of multiple errors at the same time, but I’m hoping that this is not a common event (or is it?).

anon71383850 · March 2, 2019, 3:16pm

I am experiencing the exactly same issue. My hue motion sensor stopps working randomly, coming back up and sending data again after some hours.
for me, i cannot see why and do not know what could cause it…

anyone an idea?

chris · March 2, 2019, 3:32pm

Do you have a log?

chris · March 2, 2019, 5:26pm

I have just deployed a new version of 1.1.11-SNAPSHOT of the ZigBee library. This incorporates a few more changes in the transaction management code, and reduces some logging in preparation for merging.

I’d appreciate any further feedback - if it’s looking good in the next day or so, then I will merge this, and will probably also do an update of the OH TP as well so that this will be available through standard installs in PaperUI. We can also then update the binding with some of the new features in the library…

scottk · March 2, 2019, 6:23pm

My test system is currently running OH-2.5.0-SNAPSHOT #1544, with the 2019-03-02 build of the 1.1.11-SNAPSHOT ZigBee library. Before upgrading to build #1544, my test system was running OH-2.5.0-SNAPSHOT #1542. Prior to the upgrade, I deleted the 2019-02-27 build of the 1.1.11-SNAPSHOT of the ZigBee library and cleared both cache and tmp.

While the system was down, I copied all of the ZigBee library bundles (your latest build) to addons/. The only ZigBee devices on the system are a CC2531 coordinator and a Hue motion sensor. The motion sensor had been working before I stopped the system. On the initial start of SNAPSHOT #1544, the Hue motion sensor thing never changes state from INITIALIZING.

zigbee:coordinator_cc2531:1685d859420 (Type=Bridge, Status=ONLINE, Label=CC2531EMK Coordinator, Bridge=null)
zigbee:philips_sml001:1685d859420:0017880104b5e741 (Type=Thing, Status=INITIALIZING, Label=Philips SML001, Bridge=zigbee:coordinator_cc2531:1685d859420)

Debug logs from the first OH start with the 2019-03-02 build of the ZigBee libraries in place:

2019-03-02 10:49:37.614 [DEBUG][/openhab/addons][smartsystems.zigbee.dongle.telegesis] - BundleEvent INSTALLED - com.zsmartsystems.zigbee.dongle.telegesis
2019-03-02 10:49:37.621 [DEBUG][/openhab/addons][m.zsmartsystems.zigbee.dongle.cc2531] - BundleEvent INSTALLED - com.zsmartsystems.zigbee.dongle.cc2531
2019-03-02 10:49:37.626 [DEBUG][/openhab/addons][com.zsmartsystems.zigbee.dongle.xbee] - BundleEvent INSTALLED - com.zsmartsystems.zigbee.dongle.xbee
2019-03-02 10:49:37.637 [DEBUG][/openhab/addons][com.zsmartsystems.zigbee            ] - BundleEvent INSTALLED - com.zsmartsystems.zigbee
2019-03-02 10:49:37.643 [DEBUG][/openhab/addons][om.zsmartsystems.zigbee.dongle.ember] - BundleEvent INSTALLED - com.zsmartsystems.zigbee.dongle.ember
2019-03-02 10:49:37.706 [DEBUG][af-d07e4b5f2542][smartsystems.zigbee.dongle.telegesis] - BundleEvent RESOLVED - com.zsmartsystems.zigbee.dongle.telegesis
2019-03-02 10:49:37.712 [DEBUG][af-d07e4b5f2542][m.zsmartsystems.zigbee.dongle.cc2531] - BundleEvent RESOLVED - com.zsmartsystems.zigbee.dongle.cc2531
2019-03-02 10:49:37.715 [DEBUG][af-d07e4b5f2542][com.zsmartsystems.zigbee.dongle.xbee] - BundleEvent RESOLVED - com.zsmartsystems.zigbee.dongle.xbee
2019-03-02 10:49:37.717 [DEBUG][af-d07e4b5f2542][com.zsmartsystems.zigbee            ] - BundleEvent RESOLVED - com.zsmartsystems.zigbee
2019-03-02 10:49:37.720 [DEBUG][af-d07e4b5f2542][om.zsmartsystems.zigbee.dongle.ember] - BundleEvent RESOLVED - com.zsmartsystems.zigbee.dongle.ember
2019-03-02 10:49:37.725 [DEBUG][/openhab/addons][com.zsmartsystems.zigbee            ] - BundleEvent STARTING - com.zsmartsystems.zigbee
2019-03-02 10:49:37.727 [DEBUG][/openhab/addons][com.zsmartsystems.zigbee            ] - BundleEvent STARTED - com.zsmartsystems.zigbee
2019-03-02 10:49:37.729 [DEBUG][/openhab/addons][m.zsmartsystems.zigbee.dongle.cc2531] - BundleEvent STARTING - com.zsmartsystems.zigbee.dongle.cc2531
2019-03-02 10:49:37.730 [DEBUG][/openhab/addons][m.zsmartsystems.zigbee.dongle.cc2531] - BundleEvent STARTED - com.zsmartsystems.zigbee.dongle.cc2531
2019-03-02 10:49:37.731 [DEBUG][/openhab/addons][smartsystems.zigbee.dongle.telegesis] - BundleEvent STARTING - com.zsmartsystems.zigbee.dongle.telegesis
2019-03-02 10:49:37.732 [DEBUG][/openhab/addons][smartsystems.zigbee.dongle.telegesis] - BundleEvent STARTED - com.zsmartsystems.zigbee.dongle.telegesis
2019-03-02 10:49:37.733 [DEBUG][/openhab/addons][om.zsmartsystems.zigbee.dongle.ember] - BundleEvent STARTING - com.zsmartsystems.zigbee.dongle.ember
2019-03-02 10:49:37.734 [DEBUG][/openhab/addons][om.zsmartsystems.zigbee.dongle.ember] - BundleEvent STARTED - com.zsmartsystems.zigbee.dongle.ember
2019-03-02 10:49:37.736 [DEBUG][/openhab/addons][com.zsmartsystems.zigbee.dongle.xbee] - BundleEvent STARTING - com.zsmartsystems.zigbee.dongle.xbee
2019-03-02 10:49:37.736 [DEBUG][/openhab/addons][com.zsmartsystems.zigbee.dongle.xbee] - BundleEvent STARTED - com.zsmartsystems.zigbee.dongle.xbee
2019-03-02 10:49:44.890 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee          ] - BundleEvent [unknown:512] - org.openhab.binding.zigbee
2019-03-02 10:49:44.895 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.openhab.binding.zigbee.converter.ZigBeeChannelConverterFactory}={service.id=348, service.bundleid=239, service.scope=bundle, component.name=org.openhab.binding.zigbee.internal.converter.ZigBeeChannelConverterFactoryImpl, component.id=192} - org.openhab.binding.zigbee
2019-03-02 10:49:44.896 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee          ] - BundleEvent STARTING - org.openhab.binding.zigbee
2019-03-02 10:49:44.897 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee          ] - BundleEvent STARTED - org.openhab.binding.zigbee
2019-03-02 10:49:44.908 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=349, service.bundleid=239, service.scope=bundle, component.name=org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService, component.id=193} - org.openhab.binding.zigbee
2019-03-02 10:49:44.909 [DEBUG][af-d07e4b5f2542][bee.discovery.ZigBeeDiscoveryService] - Starting ZigBeeDiscoveryService
2019-03-02 10:49:44.950 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.openhab.binding.zigbee.converter.ZigBeeChannelConverterProvider}={service.id=350, service.bundleid=239, service.scope=bundle, component.name=org.openhab.binding.zigbee.internal.converter.ZigBeeDefaultChannelConverterProvider, component.id=194} - org.openhab.binding.zigbee
2019-03-02 10:49:44.951 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicCommandDescriptionProvider}={service.id=351, service.bundleid=239, service.scope=bundle, component.name=org.openhab.binding.zigbee.internal.converter.warningdevice.DynamicWarningCommandDescriptionProvider, component.id=195} - org.openhab.binding.zigbee
2019-03-02 10:49:44.956 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryParticipant}={service.id=352, service.bundleid=239, service.scope=bundle, component.name=org.openhab.binding.zigbee.discovery.internal.ZigBeeDefaultDiscoveryParticipant, component.id=196} - org.openhab.binding.zigbee
2019-03-02 10:49:44.961 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=353, service.bundleid=239, service.scope=bundle, component.name=org.openhab.binding.zigbee.internal.ZigBeeHandlerFactory, component.id=197} - org.openhab.binding.zigbee
2019-03-02 10:49:44.971 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.xbee     ] - BundleEvent [unknown:512] - org.openhab.binding.zigbee.xbee
2019-03-02 10:49:44.979 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.xbee     ] - BundleEvent STARTING - org.openhab.binding.zigbee.xbee
2019-03-02 10:49:44.980 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.xbee     ] - BundleEvent STARTED - org.openhab.binding.zigbee.xbee
2019-03-02 10:49:44.983 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.xbee     ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=354, service.bundleid=243, service.scope=bundle, component.name=org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory, component.id=198} - org.openhab.binding.zigbee.xbee
2019-03-02 10:49:44.986 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.telegesis] - BundleEvent [unknown:512] - org.openhab.binding.zigbee.telegesis
2019-03-02 10:49:44.988 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.telegesis] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.usbserial.UsbSerialDiscoveryParticipant}={service.id=355, service.bundleid=242, service.scope=bundle, component.name=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant, component.id=199} - org.openhab.binding.zigbee.telegesis
2019-03-02 10:49:44.996 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.telegesis] - BundleEvent STARTING - org.openhab.binding.zigbee.telegesis
2019-03-02 10:49:44.997 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.telegesis] - BundleEvent STARTED - org.openhab.binding.zigbee.telegesis
2019-03-02 10:49:45.002 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.telegesis] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=356, service.bundleid=242, service.scope=bundle, component.name=org.openhab.binding.zigbee.telegesis.internal.TelegesisHandlerFactory, component.id=200} - org.openhab.binding.zigbee.telegesis
2019-03-02 10:49:45.004 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.ember    ] - BundleEvent [unknown:512] - org.openhab.binding.zigbee.ember
2019-03-02 10:49:45.006 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.ember    ] - BundleEvent STARTING - org.openhab.binding.zigbee.ember
2019-03-02 10:49:45.007 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.ember    ] - BundleEvent STARTED - org.openhab.binding.zigbee.ember
2019-03-02 10:49:45.010 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.ember    ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=357, service.bundleid=241, service.scope=bundle, component.name=org.openhab.binding.zigbee.ember.internal.EmberHandlerFactory, component.id=201} - org.openhab.binding.zigbee.ember
2019-03-02 10:49:45.011 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.ember    ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.usbserial.UsbSerialDiscoveryParticipant}={service.id=358, service.bundleid=241, service.scope=bundle, component.name=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant, component.id=202} - org.openhab.binding.zigbee.ember
2019-03-02 10:49:45.012 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.cc2531   ] - BundleEvent [unknown:512] - org.openhab.binding.zigbee.cc2531
2019-03-02 10:49:45.013 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.cc2531   ] - BundleEvent STARTING - org.openhab.binding.zigbee.cc2531
2019-03-02 10:49:45.014 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.cc2531   ] - BundleEvent STARTED - org.openhab.binding.zigbee.cc2531
2019-03-02 10:49:45.016 [DEBUG][af-d07e4b5f2542][org.openhab.binding.zigbee.cc2531   ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=359, service.bundleid=240, service.scope=bundle, component.name=org.openhab.binding.zigbee.cc2531.internal.CC2531HandlerFactory, component.id=203} - org.openhab.binding.zigbee.cc2531
2019-03-02 10:49:45.051 [DEBUG][le-processing-5][org.openhab.binding.zigbee.cc2531   ] - ServiceEvent REGISTERED - {org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler}={service.id=361, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zigbee.cc2531
2019-03-02 10:49:45.098 [DEBUG][     safeCall-6][.zigbee.cc2531.handler.CC2531Handler] - Initializing ZigBee CC2531 serial bridge handler.
2019-03-02 10:49:45.099 [DEBUG][     safeCall-6][bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_cc2531:1685d859420].
2019-03-02 10:49:45.103 [DEBUG][     safeCall-6][bee.handler.ZigBeeCoordinatorHandler] - Channel 11
2019-03-02 10:49:45.108 [DEBUG][     safeCall-6][bee.handler.ZigBeeCoordinatorHandler] - PANID 37900
2019-03-02 10:49:45.109 [DEBUG][     safeCall-6][bee.handler.ZigBeeCoordinatorHandler] - EPANID 00124B0009EB08E0
2019-03-02 10:49:45.109 [DEBUG][     safeCall-6][bee.handler.ZigBeeCoordinatorHandler] - Network Key 0B37FDA9656CFEA927ED9477C7EB5A25
2019-03-02 10:49:45.110 [DEBUG][     safeCall-6][bee.handler.ZigBeeCoordinatorHandler] - Link Key 5A6967426565416C6C69616E63653039
2019-03-02 10:49:45.110 [DEBUG][     safeCall-6][bee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=false
2019-03-02 10:49:45.111 [DEBUG][     safeCall-6][bee.handler.ZigBeeCoordinatorHandler] - Network Key String 0B37FDA9656CFEA927ED9477C7EB5A25
2019-03-02 10:49:45.112 [DEBUG][     safeCall-6][bee.handler.ZigBeeCoordinatorHandler] - Network key final array 0B37FDA9656CFEA927ED9477C7EB5A25
2019-03-02 10:49:45.112 [DEBUG][     safeCall-6][bee.handler.ZigBeeCoordinatorHandler] - Link Key String 5A6967426565416C6C69616E63653039
2019-03-02 10:49:45.113 [DEBUG][     safeCall-6][bee.handler.ZigBeeCoordinatorHandler] - Link key final array 5A6967426565416C6C69616E63653039
2019-03-02 10:49:45.126 [DEBUG][     safeCall-6][.zigbee.cc2531.handler.CC2531Handler] - ZigBee CC2531 Coordinator opening Port:'/dev/ttyACM0' PAN:940c, EPAN:00124B0009EB08E0, Channel:11
2019-03-02 10:49:45.147 [DEBUG][     safeCall-6][bee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
2019-03-02 10:49:45.169 [DEBUG][-thingManager-1][org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=372, service.bundleid=239, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-02 10:49:45.171 [DEBUG][-thingManager-1][org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=373, service.bundleid=239, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-02 10:49:45.182 [DEBUG][-thingManager-1][org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=375, service.bundleid=239, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-02 10:49:45.198 [DEBUG][     safeCall-6][ng.zigbee.handler.ZigBeeThingHandler] - 0017880104B5E741: Initializing ZigBee thing handler zigbee:philips_sml001:1685d859420:0017880104b5e741
2019-03-02 10:49:45.200 [DEBUG][ngLinkManager-2][ng.zigbee.handler.ZigBeeThingHandler] - 0017880104B5E741: Channel zigbee:philips_sml001:1685d859420:0017880104b5e741:motion linked - polling started.
2019-03-02 10:49:45.200 [DEBUG][ngLinkManager-2][ng.zigbee.handler.ZigBeeThingHandler] - 0017880104B5E741: Channel zigbee:philips_sml001:1685d859420:0017880104b5e741:illuminance linked - polling started.
2019-03-02 10:49:45.200 [DEBUG][ngLinkManager-2][ng.zigbee.handler.ZigBeeThingHandler] - 0017880104B5E741: Channel zigbee:philips_sml001:1685d859420:0017880104b5e741:temperature linked - polling started.
2019-03-02 10:49:45.201 [DEBUG][ngLinkManager-2][ng.zigbee.handler.ZigBeeThingHandler] - 0017880104B5E741: Channel zigbee:philips_sml001:1685d859420:0017880104b5e741:battery_level linked - polling started.
2019-03-02 10:49:45.210 [DEBUG][     safeCall-6][ng.zigbee.handler.ZigBeeThingHandler] - 0017880104B5E741: Coordinator status changed to UNKNOWN.
2019-03-02 10:49:45.211 [DEBUG][     safeCall-6][ng.zigbee.handler.ZigBeeThingHandler] - 0017880104B5E741: Coordinator is unknown or not online.
2019-03-02 10:49:45.515 [DEBUG][ures-3-thread-1][com.zsmartsystems.zigbee            ] - BundleEvent STARTING - com.zsmartsystems.zigbee
2019-03-02 10:49:45.517 [DEBUG][ures-3-thread-1][com.zsmartsystems.zigbee            ] - BundleEvent STARTED - com.zsmartsystems.zigbee
2019-03-02 10:49:45.519 [DEBUG][ures-3-thread-1][m.zsmartsystems.zigbee.dongle.cc2531] - BundleEvent STARTING - com.zsmartsystems.zigbee.dongle.cc2531
2019-03-02 10:49:45.520 [DEBUG][ures-3-thread-1][m.zsmartsystems.zigbee.dongle.cc2531] - BundleEvent STARTED - com.zsmartsystems.zigbee.dongle.cc2531
2019-03-02 10:49:45.778 [DEBUG][ures-3-thread-1][smartsystems.zigbee.dongle.telegesis] - BundleEvent STARTING - com.zsmartsystems.zigbee.dongle.telegesis
2019-03-02 10:49:45.779 [DEBUG][ures-3-thread-1][smartsystems.zigbee.dongle.telegesis] - BundleEvent STARTED - com.zsmartsystems.zigbee.dongle.telegesis
2019-03-02 10:49:45.866 [DEBUG][ures-3-thread-1][com.zsmartsystems.zigbee.dongle.xbee] - BundleEvent STARTING - com.zsmartsystems.zigbee.dongle.xbee
2019-03-02 10:49:45.867 [DEBUG][ures-3-thread-1][com.zsmartsystems.zigbee.dongle.xbee] - BundleEvent STARTED - com.zsmartsystems.zigbee.dongle.xbee
2019-03-02 10:49:46.157 [DEBUG][-thingHandler-5][bee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
2019-03-02 10:49:46.158 [DEBUG][-thingHandler-5][bee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
2019-03-02 10:49:46.171 [DEBUG][-thingHandler-5][e.transaction.ZigBeeTransactionQueue] - Broadcast: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=3, interTransactionDelay=1200, maxRetries=0]
2019-03-02 10:49:46.172 [DEBUG][-thingHandler-5][e.transaction.ZigBeeTransactionQueue] - Multicast: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=3, interTransactionDelay=1200, maxRetries=0]
2019-03-02 10:49:46.172 [DEBUG][-thingHandler-5][bee.handler.ZigBeeCoordinatorHandler] - Mesh Update Period 86400
2019-03-02 10:49:46.177 [DEBUG][-thingHandler-5][tsystems.zigbee.ZigBeeNetworkManager] - Adding supported cluster 1280
2019-03-02 10:49:46.178 [DEBUG][-thingHandler-5][com.zsmartsystems.zigbee.ZigBeeNode ] - ClusterMatcher starting
2019-03-02 10:49:46.211 [DEBUG][-thingHandler-5][com.zsmartsystems.zigbee.ZigBeeNode ] - ClusterMatcher adding cluster IAS_ZONE
2019-03-02 10:49:46.211 [DEBUG][-thingHandler-5][tsystems.zigbee.ZigBeeNetworkManager] - Adding supported cluster 25
2019-03-02 10:49:46.212 [DEBUG][-thingHandler-5][com.zsmartsystems.zigbee.ZigBeeNode ] - ClusterMatcher adding cluster OTA_UPGRADE
2019-03-02 10:49:46.218 [DEBUG][-thingHandler-5][nal.ZigBeeNetworkStateSerializerImpl] - Loading ZigBee network state: Start.
2019-03-02 10:49:46.364 [DEBUG][-thingHandler-5][tsystems.zigbee.ZigBeeNetworkManager] - 00124B0009EB08E0: Node 0 added to the network
2019-03-02 10:49:46.380 [DEBUG][ures-3-thread-1][om.zsmartsystems.zigbee.dongle.ember] - BundleEvent STARTING - com.zsmartsystems.zigbee.dongle.ember
2019-03-02 10:49:46.382 [DEBUG][ures-3-thread-1][om.zsmartsystems.zigbee.dongle.ember] - BundleEvent STARTED - com.zsmartsystems.zigbee.dongle.ember
2019-03-02 10:49:46.408 [DEBUG][-thingHandler-5][tsystems.zigbee.ZigBeeNetworkManager] - 0017880104B5E741: Node 17054 added to the network
2019-03-02 10:49:46.408 [DEBUG][-thingHandler-5][nal.ZigBeeNetworkStateSerializerImpl] - Loading ZigBee network state: Done.
2019-03-02 10:49:46.413 [DEBUG][-thingHandler-5][e.dongle.cc2531.ZigBeeDongleTiCc2531] - CC2531 transport initialize
2019-03-02 10:49:46.413 [DEBUG][ool-26-thread-1][tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to INITIALISING
2019-03-02 10:49:46.414 [DEBUG][-thingHandler-5][ding.zigbee.handler.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyACM0] at 115200 baud, flow control FLOWCONTROL_OUT_RTSCTS.
2019-03-02 10:49:46.419 [DEBUG][ool-26-thread-2][bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
2019-03-02 10:49:46.469 [DEBUG][-thingHandler-5][ding.zigbee.handler.ZigBeeSerialPort] - Serial port [/dev/ttyACM0] is initialized.
2019-03-02 10:49:46.486 [DEBUG][-thingHandler-5][31.network.impl.CommandInterfaceImpl] - ->  SYS_RESET (Packet: subsystem=null, length=1, apiId=41 00, data=FE 01 41 00 01 41, checksum=41, error=false) 
2019-03-02 10:49:48.556 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-- SYS_RESET_RESPONSE (FE 06 41 80 00 02 00 02 06 03 C2)
2019-03-02 10:49:48.558 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=6, apiId=41 80, data=FE 06 41 80 00 02 00 02 06 03 C2, checksum=C2, error=false
2019-03-02 10:49:48.559 [DEBUG][-thingHandler-5][31.network.impl.CommandInterfaceImpl] - ->  SYS_VERSION (Packet: subsystem=null, length=0, apiId=21 02, data=FE 00 21 02 23, checksum=23, error=false) 
2019-03-02 10:49:48.667 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-  SYS_VERSION_RESPONSE (FE 05 61 02 02 00 02 06 03 63)
2019-03-02 10:49:48.668 [DEBUG][-thingHandler-5][.cc2531.network.ZigBeeNetworkManager] - CC2531 version is Software=2.6 Product=0 Hardware=3 Transport=2
2019-03-02 10:49:48.668 [DEBUG][-thingHandler-5][31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 01 20, checksum=20, error=false) 
2019-03-02 10:49:48.787 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 01 E0 08 EB 09 00 4B 12 00 3B)
2019-03-02 10:49:48.789 [DEBUG][-thingHandler-5][31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 05 24, checksum=24, error=false) 
2019-03-02 10:49:48.908 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 05 0B 08 EB 09 00 4B 12 00 D4)
2019-03-02 10:49:48.910 [DEBUG][-thingHandler-5][31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 06 27, checksum=27, error=false) 
2019-03-02 10:49:49.028 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 06 0C 94 EB 09 00 4B 12 00 4C)
2019-03-02 10:49:49.029 [DEBUG][-thingHandler-5][31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 07 26, checksum=26, error=false) 
2019-03-02 10:49:49.149 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 07 E0 08 EB 09 00 4B 12 00 3D)
2019-03-02 10:49:49.150 [DEBUG][-thingHandler-5][bee.handler.ZigBeeCoordinatorHandler] - ZigBee Initialise: Previous device configuration was: channel=CHANNEL_11, PanID=37900, EPanId=00124B0009EB08E0
2019-03-02 10:49:49.152 [DEBUG][-thingHandler-5][e.dongle.cc2531.ZigBeeDongleTiCc2531] - CC2531 transport startup
2019-03-02 10:49:49.153 [DEBUG][-thingHandler-5][.cc2531.network.ZigBeeNetworkManager] - Creating network as Coordinator
2019-03-02 10:49:49.153 [DEBUG][-thingHandler-5][31.network.impl.CommandInterfaceImpl] - ->  ZDO_MSG_CB_REGISTER (Packet: subsystem=null, length=2, apiId=25 3E, data=FE 02 25 3E FF FF 19, checksum=19, error=false) 
2019-03-02 10:49:49.269 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-  ZDO_MSG_CB_REGISTER_SRSP (FE 01 65 3E 00 5A)
2019-03-02 10:49:49.270 [DEBUG][-thingHandler-5][31.network.impl.CommandInterfaceImpl] - ->  ZB_WRITE_CONFIGURATION (Packet: subsystem=null, length=3, apiId=26 05, data=FE 03 26 05 8F 01 01 AF, checksum=AF, error=false) 
2019-03-02 10:49:49.390 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-  ZB_WRITE_CONFIGURATION_RSP (FE 01 66 05 00 62)
2019-03-02 10:49:49.390 [DEBUG][-thingHandler-5][31.network.impl.CommandInterfaceImpl] - ->  ZDO_STARTUP_FROM_APP (Packet: subsystem=null, length=2, apiId=25 40, data=FE 02 25 40 00 00 67, checksum=67, error=false) 
2019-03-02 10:49:50.488 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-  ZDO_STARTUP_FROM_APP_SRSP (FE 01 65 40 00 24)
2019-03-02 10:49:50.488 [INFO ][-thingHandler-5][.cc2531.network.ZigBeeNetworkManager] - Initialized ZigBee network with existing network state.
2019-03-02 10:49:50.489 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-- ZDO_STATE_CHANGE_IND (FE 01 45 C0 09 8D)
2019-03-02 10:49:50.490 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - Received Async Cmd: ZDO_STATE_CHANGE_IND{State=DEV_COORD_STARTED}
2019-03-02 10:49:50.490 [DEBUG][oolPacketParser][e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45c0
2019-03-02 10:49:50.491 [DEBUG][oolPacketParser][.cc2531.network.ZigBeeNetworkManager] - Started as ZigBee Coordinator
2019-03-02 10:49:50.540 [DEBUG][-thingHandler-5][31.network.impl.CommandInterfaceImpl] - ->  AF_REGISTER (Packet: subsystem=null, length=11, apiId=24 00, data=FE 0B 24 00 01 04 01 00 00 00 00 00 01 00 05 2F, checksum=2F, error=false) 
2019-03-02 10:49:50.646 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-  AF_REGISTER_SRSP (FE 01 64 00 00 65)
2019-03-02 10:49:50.647 [DEBUG][-thingHandler-5][e.dongle.cc2531.ZigBeeDongleTiCc2531] - Registered endpoint 1 with profile: 260
2019-03-02 10:49:50.647 [DEBUG][-thingHandler-5][31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 05 24, checksum=24, error=false) 
2019-03-02 10:49:50.647 [DEBUG][ool-26-thread-2][tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to ONLINE
2019-03-02 10:49:50.648 [DEBUG][ool-26-thread-2][p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Startup
2019-03-02 10:49:50.651 [DEBUG][ool-26-thread-2][pp.discovery.ZigBeeNetworkDiscoverer] - Network discovery task: starting
2019-03-02 10:49:50.651 [DEBUG][ool-26-thread-2][pp.discovery.ZigBeeNetworkDiscoverer] - 0: NWK Discovery scheduling node discovery
2019-03-02 10:49:50.653 [DEBUG][ool-24-thread-1][pp.discovery.ZigBeeNetworkDiscoverer] - 0: NWK Discovery starting node discovery
2019-03-02 10:49:50.660 [DEBUG][ool-24-thread-1][transaction.ZigBeeTransactionManager] - 00124B0009EB08E0: Creating new Transaction Queue
2019-03-02 10:49:50.661 [DEBUG][ool-24-thread-1][e.transaction.ZigBeeTransactionQueue] - 00124B0009EB08E0: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=50, maxRetries=2]
2019-03-02 10:49:50.662 [DEBUG][ool-24-thread-1][e.transaction.ZigBeeTransactionQueue] - 00124B0009EB08E0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0/0 -> 0/0, cluster=0001, TID=--, nwkAddrOfInterest=0, requestType=1, startIndex=0]]
2019-03-02 10:49:50.663 [DEBUG][ool-24-thread-1][transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0/0 -> 0/0, cluster=0001, TID=00, nwkAddrOfInterest=0, requestType=1, startIndex=0]]
2019-03-02 10:49:50.663 [DEBUG][ool-24-thread-1][transaction.ZigBeeTransactionManager] - addTransactionListener: ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0/0 -> 0/0, cluster=0001, TID=00, nwkAddrOfInterest=0, requestType=1, startIndex=0]]
2019-03-02 10:49:50.663 [DEBUG][ool-24-thread-1][transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-03-02 10:49:50.665 [DEBUG][ool-24-thread-2][p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update
2019-03-02 10:49:50.669 [DEBUG][ool-24-thread-1][tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: IeeeAddressRequest [0/0 -> 0/0, cluster=0001, TID=00, nwkAddrOfInterest=0, requestType=1, startIndex=0]
2019-03-02 10:49:50.669 [DEBUG][ool-26-thread-6][bee.handler.ZigBeeCoordinatorHandler] - 00124B0009EB08E0: networkStateUpdated called with state=ONLINE
2019-03-02 10:49:50.671 [DEBUG][ool-24-thread-1][tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0001, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=00, payload=00 00 00 01 00]
2019-03-02 10:49:50.672 [DEBUG][ool-26-thread-7][p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Adding discoverer for 0017880104B5E741
2019-03-02 10:49:50.674 [DEBUG][ool-26-thread-5][p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Adding discoverer for 00124B0009EB08E0
2019-03-02 10:49:50.676 [INFO ][ESH-discovery-2][bee.discovery.ZigBeeDiscoveryService] - 0017880104B5E741: Starting ZigBee device discovery
2019-03-02 10:49:50.676 [DEBUG][ESH-discovery-2][bee.discovery.ZigBeeDiscoveryService] - 0017880104B5E741: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_cc2531:1685d859420
2019-03-02 10:49:50.680 [DEBUG][ESH-discovery-2][scovery.ZigBeeNodePropertyDiscoverer] - 0017880104B5E741: ZigBee node property discovery start
2019-03-02 10:49:50.680 [DEBUG][ESH-discovery-2][scovery.ZigBeeNodePropertyDiscoverer] - 0017880104B5E741: ZigBee node property discovery using 17054/1
2019-03-02 10:49:50.681 [DEBUG][ESH-discovery-2][scovery.ZigBeeNodePropertyDiscoverer] - 0017880104B5E741: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, modelId=SML001, zigbee_networkaddress=17054, zigbee_powersource=DISPOSABLE_BATTERY, zigbee_stkversion=1, zigbee_datecode=20160630, zigbee_zclversion=1, vendor=Philips, zigbee_powermode=RECEIVER_ON_PERIODICALLY, zigbee_powersources=[DISPOSABLE_BATTERY, MAINS, RECHARGABLE_BATTERY], hardwareVersion=1, firmwareVersion=0x420049E0}
2019-03-02 10:49:50.686 [DEBUG][ESH-discovery-2][nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state
2019-03-02 10:49:50.688 [DEBUG][ool-26-thread-5][iscovery.ZigBeeNodeServiceDiscoverer] - 00124B0009EB08E0: Node SVC Discovery: created discoverer
2019-03-02 10:49:50.689 [DEBUG][ool-26-thread-5][iscovery.ZigBeeNodeServiceDiscoverer] - 00124B0009EB08E0: Node SVC Discovery: start discovery
2019-03-02 10:49:50.689 [DEBUG][ool-26-thread-5][iscovery.ZigBeeNodeServiceDiscoverer] - 00124B0009EB08E0: Node SVC Discovery: scheduled [NEIGHBORS, NWK_ADDRESS]
2019-03-02 10:49:50.690 [DEBUG][ESH-discovery-2][nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2019-03-02 10:49:50.691 [DEBUG][ool-26-thread-7][iscovery.ZigBeeNodeServiceDiscoverer] - 0017880104B5E741: Node SVC Discovery: created discoverer
2019-03-02 10:49:50.691 [DEBUG][ool-26-thread-7][iscovery.ZigBeeNodeServiceDiscoverer] - 0017880104B5E741: Node SVC Discovery: start discovery
2019-03-02 10:49:50.691 [DEBUG][ool-26-thread-7][iscovery.ZigBeeNodeServiceDiscoverer] - 0017880104B5E741: Node SVC Discovery: scheduled [NEIGHBORS, NWK_ADDRESS]
2019-03-02 10:49:50.741 [DEBUG][ESH-discovery-2][nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2019-03-02 10:49:50.766 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 05 0B 06 00 FF FE 01 64 00 05)
2019-03-02 10:49:50.767 [DEBUG][ool-24-thread-1][31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 00 00 00 00 01 00 00 30 1F 05 00 00 00 01 00 00, checksum=00, error=false) 
2019-03-02 10:49:50.807 [DEBUG][ool-24-thread-2][iscovery.ZigBeeNodeServiceDiscoverer] - 00124B0009EB08E0: Node SVC Discovery: running NEIGHBORS
2019-03-02 10:49:50.887 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2019-03-02 10:49:50.888 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0F 45 81 00 E0 08 EB 09 00 4B 12 00 00 00 00 01 9E 42 45)
2019-03-02 10:49:50.888 [DEBUG][-thingHandler-5][31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 07 26, checksum=26, error=false) 
2019-03-02 10:49:50.888 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=15, apiId=45 81, data=FE 0F 45 81 00 E0 08 EB 09 00 4B 12 00 00 00 00 01 9E 42 45, checksum=45, error=false
2019-03-02 10:49:50.888 [DEBUG][ool-24-thread-2][e.transaction.ZigBeeTransactionQueue] - 00124B0009EB08E0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=--, startIndex=0]]
2019-03-02 10:49:50.889 [DEBUG][ool-24-thread-2][transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=01, startIndex=0]]
2019-03-02 10:49:50.889 [DEBUG][ool-24-thread-2][transaction.ZigBeeTransactionManager] - addTransactionListener: ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=01, startIndex=0]]
2019-03-02 10:49:50.890 [DEBUG][ool-24-thread-2][transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-03-02 10:49:50.890 [DEBUG][ool-24-thread-2][tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=01, startIndex=0]
2019-03-02 10:49:50.890 [DEBUG][ool-24-thread-2][tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0031, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=01, payload=00 00]
2019-03-02 10:49:50.901 [DEBUG][oolPacketParser][tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8001, addressMode=null, radius=0, apsSecurity=false, apsCounter=00, payload=00 00 E0 08 EB 09 00 4B 12 00 00 00 01 00 9E 42]
2019-03-02 10:49:50.903 [DEBUG][oolPacketParser][tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00124B0009EB08E0, nwkAddrRemoteDev=0, startIndex=0, nwkAddrAssocDevList=[17054]]
2019-03-02 10:49:50.903 [DEBUG][oolPacketParser][transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00124B0009EB08E0, nwkAddrRemoteDev=0, startIndex=0, nwkAddrAssocDevList=[17054]] 
2019-03-02 10:49:50.903 [DEBUG][oolPacketParser][transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00124B0009EB08E0, nwkAddrRemoteDev=0, startIndex=0, nwkAddrAssocDevList=[17054]] ZigBeeTransaction [queueTime=241, state=DISPATCHED, sendCnt=1, command=IeeeAddressRequest [0/0 -> 0/0, cluster=0001, TID=00, nwkAddrOfInterest=0, requestType=1, startIndex=0]]
2019-03-02 10:49:50.904 [DEBUG][oolPacketParser][transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00124B0009EB08E0, nwkAddrRemoteDev=0, startIndex=0, nwkAddrAssocDevList=[17054]] ZigBeeTransaction [queueTime=16, state=DISPATCHED, sendCnt=1, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=01, startIndex=0]]
2019-03-02 10:49:50.904 [DEBUG][ool-26-thread-7][transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=242, state=COMPLETE, sendCnt=1, command=IeeeAddressRequest [0/0 -> 0/0, cluster=0001, TID=00, nwkAddrOfInterest=0, requestType=1, startIndex=0]]
2019-03-02 10:49:50.904 [DEBUG][ool-24-thread-1][pp.discovery.ZigBeeNetworkDiscoverer] - 0: NWK Discovery IeeeAddressRequest returned IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00124B0009EB08E0, nwkAddrRemoteDev=0, startIndex=0, nwkAddrAssocDevList=[17054]]
2019-03-02 10:49:50.904 [DEBUG][ool-26-thread-7][transaction.ZigBeeTransactionManager] - removeTransactionListener: ZigBeeTransaction [queueTime=242, state=COMPLETE, sendCnt=1, command=IeeeAddressRequest [0/0 -> 0/0, cluster=0001, TID=00, nwkAddrOfInterest=0, requestType=1, startIndex=0]]
2019-03-02 10:49:50.905 [DEBUG][ool-24-thread-1][pp.discovery.ZigBeeNetworkDiscoverer] - 00124B0009EB08E0: NWK Discovery add node 0
2019-03-02 10:49:50.905 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 18 45 FF 00 00 00 01 80 00 00 00 00 00 E0 08 EB 09 00 4B 12 00 00 00 01 00 9E 42 AD)
2019-03-02 10:49:50.905 [DEBUG][ool-26-thread-7][transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-03-02 10:49:50.905 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=24, apiId=45 FF, data=FE 18 45 FF 00 00 00 01 80 00 00 00 00 00 E0 08 EB 09 00 4B 12 00 00 00 01 00 9E 42 AD, checksum=AD, error=false
2019-03-02 10:49:50.905 [DEBUG][ool-24-thread-1][com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B0009EB08E0: Node state updated from UNKNOWN to ONLINE
2019-03-02 10:49:50.905 [DEBUG][ool-24-thread-1][tsystems.zigbee.ZigBeeNetworkManager] - 00124B0009EB08E0: Node 0 update
2019-03-02 10:49:50.905 [DEBUG][oolPacketParser][tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8001, addressMode=null, radius=0, apsSecurity=false, apsCounter=00, payload=00 00 E0 08 EB 09 00 4B 12 00 00 00 01 00 9E 42]
2019-03-02 10:49:50.905 [DEBUG][oolPacketParser][tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00124B0009EB08E0, nwkAddrRemoteDev=0, startIndex=0, nwkAddrAssocDevList=[17054]]
2019-03-02 10:49:50.905 [DEBUG][ool-26-thread-5][e.transaction.ZigBeeTransactionQueue] - 00124B0009EB08E0: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=50, maxRetries=2]
2019-03-02 10:49:50.906 [DEBUG][oolPacketParser][transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00124B0009EB08E0, nwkAddrRemoteDev=0, startIndex=0, nwkAddrAssocDevList=[17054]] 
2019-03-02 10:49:50.906 [DEBUG][oolPacketParser][transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00124B0009EB08E0, nwkAddrRemoteDev=0, startIndex=0, nwkAddrAssocDevList=[17054]] ZigBeeTransaction [queueTime=18, state=DISPATCHED, sendCnt=1, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=01, startIndex=0]]
2019-03-02 10:49:50.906 [DEBUG][ool-24-thread-1][nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state
2019-03-02 10:49:50.911 [DEBUG][ool-24-thread-1][nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2019-03-02 10:49:50.929 [DEBUG][ool-24-thread-1][nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2019-03-02 10:49:50.930 [DEBUG][ool-24-thread-1][pp.discovery.ZigBeeNetworkDiscoverer] - 17054: NWK Discovery scheduling node discovery
2019-03-02 10:49:50.930 [DEBUG][ool-24-thread-5][pp.discovery.ZigBeeNetworkDiscoverer] - 17054: NWK Discovery starting node discovery
2019-03-02 10:49:50.932 [DEBUG][ool-24-thread-1][pp.discovery.ZigBeeNetworkDiscoverer] - 0: NWK Discovery ending node discovery
2019-03-02 10:49:51.009 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 07 E0 08 EB 09 00 4B 12 00 3D)
2019-03-02 10:49:51.010 [DEBUG][ool-24-thread-2][31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=12, apiId=24 01, data=FE 0C 24 01 00 00 00 00 31 00 01 30 1F 02 00 00 34, checksum=34, error=false) 
2019-03-02 10:49:51.010 [DEBUG][-thingHandler-5][bee.handler.ZigBeeCoordinatorHandler] - ZigBee Initialise done. channel=CHANNEL_11, PanId=37900  EPanId=00124B0009EB08E0
2019-03-02 10:49:51.013 [DEBUG][-thingHandler-5][tsystems.zigbee.ZigBeeNetworkManager] - Adding supported cluster 1280
2019-03-02 10:49:51.014 [DEBUG][-thingHandler-5][com.zsmartsystems.zigbee.ZigBeeNode ] - ClusterMatcher adding cluster IAS_ZONE
2019-03-02 10:49:51.014 [DEBUG][-thingManager-2][ng.zigbee.handler.ZigBeeThingHandler] - 0017880104B5E741: Coordinator status changed to ONLINE.
2019-03-02 10:49:51.016 [DEBUG][-thingManager-2][ng.zigbee.handler.ZigBeeThingHandler] - 0017880104B5E741: Coordinator is ONLINE. Starting device initialisation.
2019-03-02 10:49:51.018 [DEBUG][ool-24-thread-3][pp.discovery.ZigBeeNetworkDiscoverer] - 0017880104B5E741: NWK Discovery starting node rediscovery
2019-03-02 10:49:51.028 [DEBUG][-thingHandler-1][ng.zigbee.handler.ZigBeeThingHandler] - 0017880104B5E741: Start initialising ZigBee Thing handler
2019-03-02 10:49:51.029 [DEBUG][-thingHandler-1][scovery.ZigBeeNodePropertyDiscoverer] - 0017880104B5E741: ZigBee node property discovery start
2019-03-02 10:49:51.029 [DEBUG][-thingHandler-1][scovery.ZigBeeNodePropertyDiscoverer] - 0017880104B5E741: ZigBee node property discovery using 17054/1
2019-03-02 10:49:51.030 [DEBUG][-thingHandler-1][scovery.ZigBeeNodePropertyDiscoverer] - 0017880104B5E741: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, modelId=SML001, zigbee_networkaddress=17054, zigbee_powersource=DISPOSABLE_BATTERY, zigbee_stkversion=1, zigbee_datecode=20160630, zigbee_zclversion=1, zigbee_routes=[], zigbee_lastupdate=, zigbee_stkcompliance=0, vendor=Philips, zigbee_powermode=RECEIVER_ON_PERIODICALLY, zigbee_powersources=[DISPOSABLE_BATTERY, MAINS, RECHARGABLE_BATTERY], hardwareVersion=1, firmwareVersion=0x420049E0, zigbee_neighbors=[], zigbee_devices=[]}
2019-03-02 10:49:51.037 [DEBUG][-thingHandler-1][ng.zigbee.handler.ZigBeeThingHandler] - 0017880104B5E741: Using static definition with existing 4 channels
2019-03-02 10:49:51.038 [DEBUG][-thingHandler-1][ng.zigbee.handler.ZigBeeThingHandler] - 0017880104B5E741: Initializing channel zigbee:philips_sml001:1685d859420:0017880104b5e741:motion with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterOccupancy@149f2461
2019-03-02 10:49:51.038 [DEBUG][-thingHandler-1][l.converter.ZigBeeConverterOccupancy] - 0017880104B5E741: Initialising device occupancy cluster
2019-03-02 10:49:51.130 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2019-03-02 10:49:51.131 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 1C 45 B1 00 00 00 01 00 01 E0 08 EB 09 00 4B 12 00 41 E7 B5 04 01 88 17 00 9E 42 12 02 01 AA 55)
2019-03-02 10:49:51.131 [DEBUG][oolPacketParser][31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=28, apiId=45 B1, data=FE 1C 45 B1 00 00 00 01 00 01 E0 08 EB 09 00 4B 12 00 41 E7 B5 04 01 88 17 00 9E 42 12 02 01 AA 55, checksum=55, error=false
2019-03-02 10:49:51.132 [DEBUG][-thingHandler-1][transaction.ZigBeeTransactionManager] - 0017880104B5E741: Creating new Transaction Queue
2019-03-02 10:49:51.132 [DEBUG][-thingHandler-1][e.transaction.ZigBeeTransactionQueue] - 0017880104B5E741: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=7600, maxRetries=2]
2019-03-02 10:49:51.132 [DEBUG][oolPacketParser][tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8031, addressMode=null, radius=0, apsSecurity=false, apsCounter=00, payload=00 00 01 00 01 E0 08 EB 09 00 4B 12 00 41 E7 B5 04 01 88 17 00 9E 42 12 02 01 AA]
2019-03-02 10:49:51.133 [DEBUG][-thingHandler-1][e.transaction.ZigBeeTransactionQueue] - 0017880104B5E741: Udpdated sleepy state from false to true
2019-03-02 10:49:51.133 [DEBUG][-thingHandler-1][e.transaction.ZigBeeTransactionQueue] - 0017880104B5E741: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 17054/0, cluster=0021, TID=--, srcAddress=0017880104B5E741, srcEndpoint=2, bindCluster=1030, dstAddrMode=3, dstAddress=00124B0009EB08E0, dstEndpoint=1]]
2019-03-02 10:49:51.134 [DEBUG][-thingHandler-1][transaction.ZigBeeTransactionManager] - 17054/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 17054/0, cluster=0021, TID=02, srcAddress=0017880104B5E741, srcEndpoint=2, bindCluster=1030, dstAddrMode=3, dstAddress=00124B0009EB08E0, dstEndpoint=1]]
2019-03-02 10:49:51.134 [DEBUG][-thingHandler-1][transaction.ZigBeeTransactionManager] - addTransactionListener: ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 17054/0, cluster=0021, TID=02, srcAddress=0017880104B5E741, srcEndpoint=2, bindCluster=1030, dstAddrMode=3, dstAddress=00124B0009EB08E0, dstEndpoint=1]]
2019-03-02 10:49:51.134 [DEBUG][-thingHandler-1][transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-03-02 10:49:51.135 [DEBUG][oolPacketParser][tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=00124B0009EB08E0, extendedAddress=0017880104B5E741, networkAddress=17054, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=UNKNOWN, depth=1, lqi=170]]]
2019-03-02 10:49:51.135 [DEBUG][-thingHandler-1][tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0/0 -> 17054/0, cluster=0021, TID=02, srcAddress=0017880104B5E741, srcEndpoint=2, bindCluster=1030, dstAddrMode=3, dstAddress=00124B0009EB08E0, dstEndpoint=1]
2019-03-02 10:49:51.136 [DEBUG][oolPacketParser][transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=00124B0009EB08E0, extendedAddress=0017880104B5E741, networkAddress=17054, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=UNKNOWN, depth=1, lqi=170]]] 
2019-03-02 10:49:51.136 [DEBUG][-thingHandler-1][tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=17054/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=02, payload=00 41 E7 B5 04 01 88 17 00 02 06 04 03 E0 08 EB 09 00 4B 12 00 01]
2019-03-02 10:49:51.136 [DEBUG][oolPacketParser][transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=00124B0009EB08E0, extendedAddress=0017880104B5E741, networkAddress=17054, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=UNKNOWN, depth=1, lqi=170]]] ZigBeeTransaction [queueTime=3, state=DISPATCHED, sendCnt=1, command=BindRequest [0/0 -> 17054/0, cluster=0021, TID=02, srcAddress=0017880104B5E741, srcEndpoint=2, bindCluster=1030, dstAddrMode=3, dstAddress=00124B0009EB08E0, dstEndpoint=1]]
2019-03-02 10:49:51.137 [DEBUG][-thingHandler-1][31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=32, apiId=24 01, data=FE 20 24 01 9E 42 00 00 21 00 02 30 1F 16 00 41 E7 B5 04 01 88 17 00 02 06 04 03 E0 08 EB 09 00 4B 12 00 01 1B, checksum=1B, error=false)

The entire log, for OH startup until shutdown is more than 4X this size. If you need more I can share via Google Drive.

scottk · March 2, 2019, 6:29pm

I restarted OH and the philips_sml001 thing took a few seconds after startup to change status to ONLINE. Perhaps this is only an issue on the first start after updating the ZigBee library bundles?

So far everything with the single ZigBee end device on my test system appears to be functioning correctly.

chris · March 2, 2019, 11:22pm

Please provide the full log - this is just the initialisation and not really any communication with the device. That said, it may not help if the device isn’t communicating, but let’s see.

I don’t think updating the binding should be any difference than restarting the binding - it’s all the same…

scottk · March 3, 2019, 3:57am

The log in question is available here. I can also provide the log from the next restart of OH when the Hue motion sensor thing status changed to ONLINE shortly after OH started, just let me know whether or not it is needed.