[Solved] OH3: first time ZigBee colour bulb installation

Max_G · June 6, 2022, 2:10am

openhabian 3.2.0 - Release Build
Ip = 192.168.1.68
Release = Raspbian GNU/Linux 11 (bullseye)
Kernel = Linux 5.15.32-v7l+
Platform = Finished Raspberry Pi bluetooth helper.
Uptime = 0 day(s). 0:9:50
CPU Usage = 7.05% avg over 4 cpu(s) (4 core(s) x 1 socket(s))
CPU Load = 1m: 1.51, 5m: 1.20, 15m: 0.87

I wanted to install my first ZigBee device while on OH2… since I read there is no support for it, I proceeded with OHv3 as follows:

bought a rPi4 4GB and an Ember ZigBee dongle.
installed openHABian on it
used the openHABian menu to prepare the serial port (and rebooted)
installed the ZigBee binding
The Ember dongle was recognised as coordinator and has all fields populated and is online

UID: zigbee:coordinator_ember:9318fa5b77
label: Ember Coordinator
thingTypeUID: zigbee:coordinator_ember
configuration:
  zigbee_port: /dev/ttyUSB0
  zigbee_initialise: false
  zigbee_channel: 11
  zigbee_concentrator: 1
  zigbee_trustcentremode: TC_JOIN_SECURE
  zigbee_extendedpanid: C1A32EFB435B716E
  zigbee_flowcontrol: 1
  zigbee_baud: 115200
  zigbee_panid: 56641
  zigbee_powermode: 1
  zigbee_txpower: 0
  zigbee_networksize: 25
  zigbee_linkkey: 5A6967426565416C6C69616E63653039
  zigbee_childtimeout: 86400
  zigbee_networkkey: 9872B87B6F19BAE34C8C7E439E37E470
  zigbee_meshupdateperiod: 86400
location: Shed

I also bought some Chinese Smart bulbs, but these do not connect to or cannot be found by the coordinator… following this description.
I enabled logging in Karaf as described in the docs, but the log makes no sense to me.

2022-06-05 15:00:26.582 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:26.585 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=7, ackNum=2, reTx=false, data=F5 00 FF 00 18]
2022-06-05 15:00:26.593 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=0, reTx=false, data=F5 80 FF 00 18 02]
2022-06-05 15:00:26.597 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=7, ackNum=2, reTx=false, data=F5 00 FF 00 18]
2022-06-05 15:00:26.599 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:26.599 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:26.602 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]
2022-06-05 15:00:27.588 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:27.591 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=0, ackNum=3, reTx=false, data=F6 00 FF 00 18]
2022-06-05 15:00:27.599 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=1, reTx=false, data=F6 80 FF 00 18 02]
2022-06-05 15:00:27.602 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=0, ackNum=3, reTx=false, data=F6 00 FF 00 18]
2022-06-05 15:00:27.604 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:27.604 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:27.607 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]
2022-06-05 15:00:28.594 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:28.597 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=1, ackNum=4, reTx=false, data=F7 00 FF 00 18]
2022-06-05 15:00:28.605 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=2, reTx=false, data=F7 80 FF 00 18 02]
2022-06-05 15:00:28.608 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=1, ackNum=4, reTx=false, data=F7 00 FF 00 18]
2022-06-05 15:00:28.610 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:28.610 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:28.613 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]
2022-06-05 15:00:29.601 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:29.604 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=2, ackNum=5, reTx=false, data=F8 00 FF 00 18]
2022-06-05 15:00:29.611 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=3, reTx=false, data=F8 80 FF 00 18 02]
2022-06-05 15:00:29.614 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=2, ackNum=5, reTx=false, data=F8 00 FF 00 18]
2022-06-05 15:00:29.616 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:29.616 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:29.619 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]
2022-06-05 15:00:30.607 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:30.609 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=3, ackNum=6, reTx=false, data=F9 00 FF 00 18]
2022-06-05 15:00:30.617 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=4, reTx=false, data=F9 80 FF 00 18 02]
2022-06-05 15:00:30.620 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=3, ackNum=6, reTx=false, data=F9 00 FF 00 18]
2022-06-05 15:00:30.622 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:30.623 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:30.625 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]
2022-06-05 15:00:31.613 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:31.616 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=4, ackNum=7, reTx=false, data=FA 00 FF 00 18]
2022-06-05 15:00:31.624 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=5, reTx=false, data=FA 80 FF 00 18 02]
2022-06-05 15:00:31.626 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=4, ackNum=7, reTx=false, data=FA 00 FF 00 18]
2022-06-05 15:00:31.629 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:31.629 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:31.631 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]
2022-06-05 15:00:32.619 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:32.622 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=5, ackNum=0, reTx=false, data=FB 00 FF 00 18]
2022-06-05 15:00:32.629 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=6, reTx=false, data=FB 80 FF 00 18 02]
2022-06-05 15:00:32.632 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=5, ackNum=0, reTx=false, data=FB 00 FF 00 18]
2022-06-05 15:00:32.635 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:32.635 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:32.637 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]
2022-06-05 15:00:33.625 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:33.628 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=6, ackNum=1, reTx=false, data=FC 00 FF 00 18]
2022-06-05 15:00:33.636 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=7, reTx=false, data=FC 80 FF 00 18 02]
2022-06-05 15:00:33.638 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=6, ackNum=1, reTx=false, data=FC 00 FF 00 18]
2022-06-05 15:00:33.641 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:33.641 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:33.643 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]
2022-06-05 15:00:34.631 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:34.634 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=7, ackNum=2, reTx=false, data=FD 00 FF 00 18]
2022-06-05 15:00:34.641 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=0, reTx=false, data=FD 80 FF 00 18 02]
2022-06-05 15:00:34.644 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=7, ackNum=2, reTx=false, data=FD 00 FF 00 18]
2022-06-05 15:00:34.647 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:34.647 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:34.649 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]
2022-06-05 15:00:35.637 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:35.640 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=0, ackNum=3, reTx=false, data=FE 00 FF 00 18]
2022-06-05 15:00:35.647 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=1, reTx=false, data=FE 80 FF 00 18 02]
2022-06-05 15:00:35.650 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=0, ackNum=3, reTx=false, data=FE 00 FF 00 18]
2022-06-05 15:00:35.653 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:35.653 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:35.655 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]
2022-06-05 15:00:36.643 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:36.646 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=1, ackNum=4, reTx=false, data=FF 00 FF 00 18]
2022-06-05 15:00:36.654 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=2, reTx=false, data=FF 80 FF 00 18 02]
2022-06-05 15:00:36.657 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=1, ackNum=4, reTx=false, data=FF 00 FF 00 18]
2022-06-05 15:00:36.659 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:36.659 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:36.663 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]
2022-06-05 15:00:37.650 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:37.653 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=2, ackNum=5, reTx=false, data=00 00 FF 00 18]
2022-06-05 15:00:37.660 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=3, reTx=false, data=00 80 FF 00 18 02]
2022-06-05 15:00:37.663 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=2, ackNum=5, reTx=false, data=00 00 FF 00 18]
2022-06-05 15:00:37.665 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:37.668 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 0
2022-06-05 15:00:37.670 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]
2022-06-05 15:00:38.656 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:38.658 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=3, ackNum=6, reTx=false, data=01 00 FF 00 18]
2022-06-05 15:00:38.666 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=4, reTx=false, data=01 80 FF 00 18 02]
2022-06-05 15:00:38.668 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=3, ackNum=6, reTx=false, data=01 00 FF 00 18]
2022-06-05 15:00:38.671 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:38.674 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 0
2022-06-05 15:00:38.676 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]
2022-06-05 15:00:39.662 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:39.664 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=4, ackNum=7, reTx=false, data=02 00 FF 00 18]
2022-06-05 15:00:39.672 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=5, reTx=false, data=02 80 FF 00 18 02]
2022-06-05 15:00:39.674 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=4, ackNum=7, reTx=false, data=02 00 FF 00 18]
2022-06-05 15:00:39.677 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:39.679 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 0
2022-06-05 15:00:39.682 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]
2022-06-05 15:00:40.667 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:40.670 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=5, ackNum=0, reTx=false, data=03 00 FF 00 18]
2022-06-05 15:00:40.677 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=6, reTx=false, data=03 80 FF 00 18 02]
2022-06-05 15:00:40.680 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=5, ackNum=0, reTx=false, data=03 00 FF 00 18]
2022-06-05 15:00:40.682 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:40.683 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 0
2022-06-05 15:00:40.685 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]
2022-06-05 15:00:41.673 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:41.677 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=6, ackNum=1, reTx=false, data=04 00 FF 00 18]
2022-06-05 15:00:41.684 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=7, reTx=false, data=04 80 FF 00 18 02]
2022-06-05 15:00:41.687 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=6, ackNum=1, reTx=false, data=04 00 FF 00 18]
2022-06-05 15:00:41.689 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:41.689 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:41.692 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]
2022-06-05 15:00:42.680 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:42.682 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=7, ackNum=2, reTx=false, data=05 00 FF 00 18]
2022-06-05 15:00:42.690 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=0, reTx=false, data=05 80 FF 00 18 02]
2022-06-05 15:00:42.693 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=7, ackNum=2, reTx=false, data=05 00 FF 00 18]
2022-06-05 15:00:42.696 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:42.696 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:42.699 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]
2022-06-05 15:00:43.686 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:43.688 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=0, ackNum=3, reTx=false, data=06 00 FF 00 18]
2022-06-05 15:00:43.696 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=1, reTx=false, data=06 80 FF 00 18 02]
2022-06-05 15:00:43.699 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=0, ackNum=3, reTx=false, data=06 00 FF 00 18]
2022-06-05 15:00:43.702 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:43.702 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:43.704 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]
2022-06-05 15:00:44.692 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2022-06-05 15:00:44.694 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=1, ackNum=4, reTx=false, data=07 00 FF 00 18]
2022-06-05 15:00:44.702 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=2, reTx=false, data=07 80 FF 00 18 02]
2022-06-05 15:00:44.705 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=1, ackNum=4, reTx=false, data=07 00 FF 00 18]
2022-06-05 15:00:44.708 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2022-06-05 15:00:44.708 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2022-06-05 15:00:44.711 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]




2022-06-05 15:04:42.903 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:9318fa5b77
2022-06-05 15:04:42.906 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to FFFC/0 for 60 seconds.
2022-06-05 15:04:42.910 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2022-06-05 15:04:42.913 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2022-06-05 15:04:42.916 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFC/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=6, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=07, permitDuration=60, tcSignificance=true]]
2022-06-05 15:04:42.918 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2022-06-05 15:04:42.921 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=07, permitDuration=60, tcSignificance=true]
2022-06-05 15:04:42.925 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFC/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=07, rssi=--, lqi=--, payload=07 3C 01]
2022-06-05 15:04:42.929 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2022-06-05 15:04:42.931 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2022-06-05 15:04:42.936 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [networkId=0, status=EMBER_SUCCESS, sequence=EF]
2022-06-05 15:04:42.939 [DEBUG] [transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=9, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=08, permitDuration=60, tcSignificance=true]]
2022-06-05 15:04:42.941 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2022-06-05 15:04:42.944 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=08, permitDuration=60, tcSignificance=true]
2022-06-05 15:04:42.947 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=08, rssi=--, lqi=--, payload=08 3C 01]
2022-06-05 15:04:42.958 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=EF], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=07 3C 01]
2022-06-05 15:04:42.977 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=F0]
2022-06-05 15:04:42.980 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=F0], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=08 3C 01]
2022-06-05 15:04:42.983 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=F0, rssi=0, lqi=FF, payload=08 3C 01]
2022-06-05 15:04:42.986 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node update. NWK Address=0000
2022-06-05 15:04:42.989 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node 0000 is not updated
2022-06-05 15:04:42.992 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=08, permitDuration=60, tcSignificance=true]
2022-06-05 15:04:42.995 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=08, permitDuration=60, tcSignificance=true] 
2022-06-05 15:04:42.999 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=F1], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=08 00]
2022-06-05 15:04:43.003 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=F1, rssi=0, lqi=FF, payload=08 00]
2022-06-05 15:04:43.005 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node update. NWK Address=0000
2022-06-05 15:04:43.009 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node 0000 is not updated
2022-06-05 15:04:43.012 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=08, status=SUCCESS]
2022-06-05 15:04:43.015 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=08, status=SUCCESS] 
2022-06-05 15:04:43.018 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0000, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=F0], messageTag=08, status=EMBER_SUCCESS, messageContents=]
2022-06-05 15:04:43.022 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=08 state=RX_ACK
2022-06-05 15:04:43.025 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=08, state=RX_ACK, outstanding=2
2022-06-05 15:04:43.029 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=100, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=08, permitDuration=60, tcSignificance=true]]
2022-06-05 15:04:43.032 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2022-06-05 15:04:43.035 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: transactionComplete, state=COMPLETE, outstanding=0
2022-06-05 15:04:43.038 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3
2022-06-05 15:04:43.040 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0000, TID=08, event=RX_ACK, state=COMPLETE
2022-06-05 15:04:43.864 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_BROADCAST, indexOrDestination=FFFC, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=EF], messageTag=07, status=EMBER_SUCCESS, messageContents=]
2022-06-05 15:04:43.867 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=07 state=RX_ACK
2022-06-05 15:04:43.869 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=07, state=RX_ACK, outstanding=1
2022-06-05 15:04:43.873 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=964, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=07, permitDuration=60, tcSignificance=true]]
2022-06-05 15:04:43.876 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2022-06-05 15:04:43.878 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=COMPLETE, outstanding=0
2022-06-05 15:04:43.881 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2022-06-05 15:04:43.883 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFC, TID=07, event=RX_ACK, state=COMPLETE

What I am asking here, and what I feel I need to address first: What brand of bulb should I buy to have something others have connected successfully?
… before I even contemplate troubleshooting.

Any hints appreciated.

On a more general note: as a long-term v1 and v2 user, I struggle with the v3 UI and terminology (at least at this early stage, where I just spent 8 hours reading and 1h playing.)

Pedro_Liberal · June 6, 2022, 7:58am

Usually xiaomi aqara xiaomi and tuya zigbee stuff works. Sonoffs too.
I have no clue which bulbs you have but unwound suggest you install zigbee2mqtt and see if you have better luck with that. You basically convert the zigbee network to mqtt, which makes it a lot easier to handle everything, including error messages.

chris · June 6, 2022, 8:21am

From the log it seems that the device did not join the network - at least there is no traffic from any device.

What dongle are you using exactly, and what is the firmware version?

chris · June 6, 2022, 10:08am

Based on the log, it will not help since the device didn’t join the network. Changing things randomly is generally not a good approach to problem solving .

Max_G · June 6, 2022, 10:48am

The dongle comes up as Bus 001 Device 004: ID 1a86:7523 QinHeng Electronics CH340 serial converter. It was from an American site, bought a year ago, when I had the idea to try this.

Happy to ditch it, if one can recommend something that reliably works.
Not sure how to determine its firmware, but happy to find out when given pointers.

[edit] I bought this one: Elelabs based on the OH docs

chris · June 6, 2022, 7:12pm

What version of firmware is it running? This is important as older code may not work with newer devices due to security changes in Zigbee. You can see the firmware version in the UI in the coordinator thing.

Max_G · June 6, 2022, 9:42pm

Thank you for your help…

I did not see firmware info on the thing page…

I downloaded a python utility from GitHub and ran it after stopping OH, which provided the info below:

# [2022-06-07 07:34] openhabian@openhabian ~/elelabs/elelabs-zigbee-ezsp-utility-master $ 
python3 Elelabs_EzspFwUtility.py probe -p /dev/ttyUSB0
2022/06/07 07:34:53 Elelabs_EzspFwUtility:   Elelabs Zigbee adapter detected:
2022/06/07 07:34:53 Elelabs_EzspFwUtility:   Adapter: ELR023
2022/06/07 07:34:53 Elelabs_EzspFwUtility:   Firmware: 6.0.3-64
2022/06/07 07:34:53 Elelabs_EzspFwUtility:   EZSP v6

I initially ran it with OH still up.
The command must have ‘grabbed’ the USB port, as the coordinator went offline in OH on the Thing UI page, but it did not reveal the info seen above, only:

# [2022-06-07 07:32] openhabian@openhabian ~/elelabs/elelabs-zigbee-ezsp-utility-master $ 
python3 Elelabs_EzspFwUtility.py probe -p /dev/ttyUSB0
2022/06/07 07:32:59 Elelabs_EzspFwUtility:   EZSP adapter in bootloader mode detected:
2022/06/07 07:32:59 Elelabs_EzspFwUtility:   	`

chris · June 6, 2022, 10:17pm

I think from memory it’s one of the properties in the coordinator, but I’m not in front of my system. It’s possible the UI presents this differently for the firmware…

Anyway, I think 6.0 is too old. From the docs, 6.4 is the minimum version for Zigbee3.0. That said, I’m not 100% sure that’s the only problem since normally old devices would be seen to join the network, then basically not work (since they leave if they don’t get the correct security response).

Depending on the bulb you have, it is often a good idea to start the join process in OH (ie start the scan), and then immediately reset the bulb (often by power cycling 5 times, or something like that). By doing the reset, the bulb should go into join mode where it searches for a network - if you don’t do this, it’s difficult to know sometimes if the device will automatically scan for a network it can join, or if it’s given up, or who knows…

Pedro_Liberal · June 6, 2022, 10:21pm

Nothing against a more systematic approach to problem solving @chris , but, as long as you take note of what you are changing then it’s not randomly, nor is it a bad idea.
Do you waste 5 hours running memtest on a stick of ram, or to do replace it with the one you have stock to see if the problem is fixed?
The user can boot up zigbee2mqtt and see if it fixes it.
If not, no harm done, it’s probably the stick, the firmware or maybe the permissions (I had to sudo chmod 777 my sonoff stick to be able to read from it).
If yes, problem solved, get on with it.

No need to waste too much time investigating certain things IMO.

chris · June 6, 2022, 10:29pm

Based on the fact that the device didn’t join the network, it will not help.

Given there are logs, IMHO it’s good to work through the issue - changing stuff to see what works doesn’t answer the “why” or “what”. I agree though - maybe “random” was not the best description, but working through things systematically is always best (IMHO - but then I’m a systems engineer ).

Max_G · June 6, 2022, 10:50pm

Alright… in anticipation that the firmware needs updating… I did just that.

# [2022-06-07 08:11] openhabian@openhabian ~/elelabs/elelabs-zigbee-ezsp-utility-master $ 
python3 Elelabs_EzspFwUtility.py ele_update -p /dev/ttyUSB0 -v zigbee
2022/06/07 08:11:51 Elelabs_EzspFwUtility:   Elelabs Zigbee adapter detected:
2022/06/07 08:11:51 Elelabs_EzspFwUtility:   Adapter: ELR023
2022/06/07 08:11:51 Elelabs_EzspFwUtility:   Firmware: 6.0.3-64
2022/06/07 08:11:51 Elelabs_EzspFwUtility:   EZSP v6
2022/06/07 08:11:52 Elelabs_EzspFwUtility:   Elelabs Zigbee adapter detected:
2022/06/07 08:11:52 Elelabs_EzspFwUtility:   Adapter: ELR023
2022/06/07 08:11:52 Elelabs_EzspFwUtility:   Firmware: 6.0.3-64
2022/06/07 08:11:52 Elelabs_EzspFwUtility:   EZSP v6
2022/06/07 08:11:52 Elelabs_EzspFwUtility:   Launch in bootloader mode
2022/06/07 08:12:01 Elelabs_EzspFwUtility:   EZSP adapter in bootloader mode detected:
2022/06/07 08:12:01 Elelabs_EzspFwUtility:   Gecko Bootloader v1.A.0
2022/06/07 08:12:02 Elelabs_EzspFwUtility:   Successfully restarted into X-MODEM mode! Starting upload of the new firmware... DO NOT INTERRUPT(!)
.....
.....
.....
.....
.....
.....
.....
.....
.....
.....
.....
.....
.....
.....
.....
.....
.....
.....

2022/06/07 08:12:43 Elelabs_EzspFwUtility:   Firmware upload complete
2022/06/07 08:12:43 Elelabs_EzspFwUtility:   Rebooting NCP...
2022/06/07 08:12:50 Elelabs_EzspFwUtility:   Elelabs Zigbee adapter detected:
2022/06/07 08:12:50 Elelabs_EzspFwUtility:   Adapter: ELR023
2022/06/07 08:12:50 Elelabs_EzspFwUtility:   Firmware: 6.10.3-41
2022/06/07 08:12:50 Elelabs_EzspFwUtility:   EZSP v8
# [2022-06-07 08:12] openhabian@openhabian ~/elelabs/elelabs-zigbee-ezsp-utility-master $

We are now on Firmware: 6.10.3-41.
After that, OH did no longer find the coordinator.

ls -l /dev/serial/by-id
total 0
lrwxrwxrwx 1 root root 13 Jun  7 08:24 usb-1a86_USB2.0-Serial-if00-port0 -> ../../ttyUSB1

showed me that it is now on USB1…

I deleted the thing and created a new one…

It did not read the coordinator data/config…

Another probe confirmed:

# [2022-06-07 08:25] openhabian@openhabian ~/elelabs/elelabs-zigbee-ezsp-utility-master $ 
python3 Elelabs_EzspFwUtility.py probe -p /dev/ttyUSB1
2022/06/07 08:25:14 Elelabs_EzspFwUtility:   Elelabs Zigbee adapter detected:
2022/06/07 08:25:14 Elelabs_EzspFwUtility:   Adapter: ELR023
2022/06/07 08:25:14 Elelabs_EzspFwUtility:   Firmware: 6.10.3-41
2022/06/07 08:25:14 Elelabs_EzspFwUtility:   EZSP v8

the coordinator can be ‘talked’ to.

OH log gave me this:

2022-06-07 08:25:59.519 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (284)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(309)] : dm ZigBeeCoordinatorHandler tracking 7 MultipleDynamic added {org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler}={service.id=529, service.bundleid=289, service.scope=singleton} (enter)
2022-06-07 08:25:59.522 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (284)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(309)] : dm ZigBeeCoordinatorHandler tracking 7 MultipleDynamic already active, binding {org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler}={service.id=529, service.bundleid=289, service.scope=singleton}
2022-06-07 08:25:59.524 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (284)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(309)] : invoking bind: addZigBeeCoordinatorHandler: parameters [org.openhab.binding.zigbee.ember.handler.EmberHandler]
2022-06-07 08:25:59.525 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (284)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(309)] : invoked bind: addZigBeeCoordinatorHandler
2022-06-07 08:25:59.528 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (284)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(309)] : dm ZigBeeCoordinatorHandler tracking 7 MultipleDynamic added {org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler}={service.id=529, service.bundleid=289, service.scope=singleton} (exit)
2022-06-07 08:25:59.601 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_ember:20f9223599].
2022-06-07 08:25:59.604 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel 0
2022-06-07 08:25:59.605 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - PANID 0
2022-06-07 08:25:59.607 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EPANID 0000000000000000
2022-06-07 08:25:59.608 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2022-06-07 08:25:59.610 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key 5A 69 67 42 65 65 41 6C 6C 69 61 6E 63 65 30 39
2022-06-07 08:25:59.611 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=true
2022-06-07 08:25:59.613 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ExtendedPanId or PanId not set: initializeNetwork=true
2022-06-07 08:25:59.614 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key String 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2022-06-07 08:25:59.617 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network key initialised A6EFD772753557C62E967878410BBC80
2022-06-07 08:25:59.619 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network key final array A6EFD772753557C62E967878410BBC80
2022-06-07 08:25:59.620 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key String 5A 69 67 42 65 65 41 6C 6C 69 61 6E 63 65 30 39
2022-06-07 08:25:59.622 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising network
2022-06-07 08:25:59.623 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel set to 11.
2022-06-07 08:25:59.669 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Created random ZigBee PAN ID [8203].
2022-06-07 08:25:59.688 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Created random ZigBee extended PAN ID [4242C2C74FDB26BF].
2022-06-07 08:25:59.726 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link key final array 5A6967426565416C6C69616E63653039
2022-06-07 08:25:59.728 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - Initializing ZigBee Ember serial bridge handler.
2022-06-07 08:25:59.732 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - ZigBee Ember Coordinator opening Port:'/dev/ttyUSB1' PAN:8203, EPAN:4242C2C74FDB26BF, Channel:11
2022-06-07 08:25:59.733 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - Ember end device poll timeout set to (169 * 2^9) = 86528 seconds
2022-06-07 08:25:59.736 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
2022-06-07 08:26:00.738 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
2022-06-07 08:26:00.739 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
2022-06-07 08:26:00.742 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Default: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
2022-06-07 08:26:00.744 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=4000, maxRetries=0]
2022-06-07 08:26:00.745 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Multicast: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=3, interTransactionDelay=1200, maxRetries=0]
2022-06-07 08:26:00.747 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - Creating ZigBee persistence folder /var/lib/openhab/zigbee/zigbee_coordinator_ember_20f9223599/
2022-06-07 08:26:00.749 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager initialize: networkState=UNINITIALISED
2022-06-07 08:26:00.750 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to INITIALISING
2022-06-07 08:26:00.752 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: Initialize with protocol ASH2.
2022-06-07 08:26:00.752 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
2022-06-07 08:26:00.754 [DEBUG] [nding.zigbee.serial.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyUSB1] at 115200 baud, flow control FLOWCONTROL_OUT_RTSCTS.
2022-06-07 08:26:00.794 [DEBUG] [nding.zigbee.serial.ZigBeeSerialPort] - Serial port [/dev/ttyUSB1] is initialized.
2022-06-07 08:26:03.123 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Ember: Link State change to true, initialised=false, networkStateUp=false
2022-06-07 08:26:03.125 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Ember: Link State change to true ignored.
2022-06-07 08:26:03.134 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetLibraryStatusResponse [networkId=0, status=UNKNOWN]
2022-06-07 08:26:10.798 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - No response from ezspVersion command
2022-06-07 08:26:10.800 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: Version returned null. ASH/EZSP not initialised.
2022-06-07 08:26:10.802 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to OFFLINE
2022-06-07 08:26:10.803 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=OFFLINE
2022-06-07 08:26:11.822 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2022-06-07 08:40:51.775 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetNodeIdResponse [networkId=0, nodeId=0000]
2022-06-07 08:40:51.781 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager transport state updated to ONLINE
2022-06-07 08:40:51.822 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFC/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=00, rssi=--, lqi=--, payload=00 00 01]
2022-06-07 08:40:51.835 [DEBUG] [transaction.ZigBeeTransactionManager] - CCCCCCFFFEA5F359: Creating new Transaction Queue
2022-06-07 08:40:51.838 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
2022-06-07 08:40:51.841 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true]]
2022-06-07 08:40:51.843 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2022-06-07 08:40:51.845 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [networkId=0, status=EMBER_SUCCESS, sequence=B5]
2022-06-07 08:40:51.846 [DEBUG] [transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=6, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=01, permitDuration=0, tcSignificance=true]]
2022-06-07 08:40:51.848 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2022-06-07 08:40:51.851 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=01, permitDuration=0, tcSignificance=true]
2022-06-07 08:40:51.854 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=01, rssi=--, lqi=--, payload=01 00 01]
2022-06-07 08:40:51.859 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Startup
2022-06-07 08:40:51.866 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - Network discovery task: starting
2022-06-07 08:40:51.871 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for 0000 scheduling node discovery
2022-06-07 08:40:51.872 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B5], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=00 00 01]
2022-06-07 08:40:51.877 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for 0000 starting node discovery
2022-06-07 08:40:51.880 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state ONLINE: Notifying node CCCCCCFFFEA5F359 [0000]
2022-06-07 08:40:51.882 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=--, nwkAddrOfInterest=0000, requestType=1, startIndex=0]]
2022-06-07 08:40:51.884 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=1, sleepy=0/3
2022-06-07 08:40:51.886 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=B6]
2022-06-07 08:40:51.888 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update
2022-06-07 08:40:51.891 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B6], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=01 00 01]
2022-06-07 08:40:51.894 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B6, rssi=0, lqi=FF, payload=01 00 01]
2022-06-07 08:40:51.895 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=1, sleepy=0/3
2022-06-07 08:40:51.900 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
2022-06-07 08:40:51.901 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node update. NWK Address=0000
2022-06-07 08:40:51.904 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - CCCCCCFFFEA5F359: Node state updated from UNKNOWN to ONLINE
2022-06-07 08:40:51.904 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - CCCCCCFFFEA5F359: Data store: Deferring write for 250ms.
2022-06-07 08:40:51.922 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - CCCCCCFFFEA5F359: networkStateUpdated called with state=ONLINE
2022-06-07 08:40:51.924 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - CCCCCCFFFEA5F359: DISCOVERY Extension: Adding discoverer for node
2022-06-07 08:40:51.926 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
2022-06-07 08:40:51.933 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - CCCCCCFFFEA5F359: Data store: Deferring write for 250ms.
2022-06-07 08:40:52.192 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - CCCCCCFFFEA5F359: Data store: Writing node.
2022-06-07 08:40:52.547 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: created discoverer
2022-06-07 08:40:52.550 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: start discovery
2022-06-07 08:40:52.555 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: starting new tasks [POWER_DESCRIPTOR, NODE_DESCRIPTOR]
2022-06-07 08:40:52.561 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: scheduled [NODE_DESCRIPTOR, POWER_DESCRIPTOR]
2022-06-07 08:40:52.567 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - CCCCCCFFFEA5F359: DISCOVERY Extension: Creating new discoverer for node
2022-06-07 08:40:52.571 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: stopped
2022-06-07 08:40:52.574 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: created discoverer
2022-06-07 08:40:52.576 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: start discovery
2022-06-07 08:40:52.579 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: starting new tasks [POWER_DESCRIPTOR, NODE_DESCRIPTOR]
2022-06-07 08:40:52.582 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: scheduled [NODE_DESCRIPTOR, POWER_DESCRIPTOR]
2022-06-07 08:40:52.628 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - CCCCCCFFFEA5F359: ZigBee saving network state complete.
2022-06-07 08:40:52.645 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=01, permitDuration=0, tcSignificance=true]
2022-06-07 08:40:52.647 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=01, permitDuration=0, tcSignificance=true] 
2022-06-07 08:40:52.654 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B7], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=01 80]
2022-06-07 08:40:52.656 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B7, rssi=0, lqi=FF, payload=01 80]
2022-06-07 08:40:52.659 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node update. NWK Address=0000
2022-06-07 08:40:52.662 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node 0000 is not updated
2022-06-07 08:40:52.667 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=01, status=INV_REQUESTTYPE]
2022-06-07 08:40:52.669 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=01, status=INV_REQUESTTYPE] 
2022-06-07 08:40:52.672 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0000, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B6], messageTag=01, status=EMBER_SUCCESS, messageContents=]
2022-06-07 08:40:52.677 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=01 state=RX_ACK
2022-06-07 08:40:52.680 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=01, state=RX_ACK, outstanding=2
2022-06-07 08:40:52.681 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetNetworkParametersResponse [networkId=0, status=EMBER_SUCCESS, nodeType=EMBER_COORDINATOR, parameters=EmberNetworkParameters [extendedPanId=CC9BFCE8D5BFBB7E, panId=78F1, radioTxPower=-1, radioChannel=11, joinMethod=EMBER_USE_MAC_ASSOCIATION, nwkManagerId=0000, nwkUpdateId=0, channels=07FFF800]]
2022-06-07 08:40:52.688 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=848, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=01, permitDuration=0, tcSignificance=true]]
2022-06-07 08:40:52.690 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2022-06-07 08:40:52.692 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: transactionComplete, state=COMPLETE, outstanding=0
2022-06-07 08:40:52.694 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2022-06-07 08:40:52.697 [DEBUG] [transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=815, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]]
2022-06-07 08:40:52.698 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2022-06-07 08:40:52.701 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]
2022-06-07 08:40:52.704 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=02, rssi=--, lqi=--, payload=02 00 00 01 00]
2022-06-07 08:40:52.707 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0000, TID=01, event=RX_ACK, state=COMPLETE
2022-06-07 08:40:52.722 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=B8]
2022-06-07 08:40:52.746 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0001, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B8], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=02 00 00 01 00]
2022-06-07 08:40:52.748 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B8, rssi=0, lqi=FF, payload=02 00 00 01 00]
2022-06-07 08:40:52.751 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node update. NWK Address=0000
2022-06-07 08:40:52.754 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node 0000 is not updated
2022-06-07 08:40:52.756 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]
2022-06-07 08:40:52.759 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0] 
2022-06-07 08:40:52.762 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8001, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B9], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=02 00 59 F3 A5 FE FF CC CC CC 00 00 00]
2022-06-07 08:40:52.765 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B9, rssi=0, lqi=FF, payload=02 00 59 F3 A5 FE FF CC CC CC 00 00 00]
2022-06-07 08:40:52.768 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node update. NWK Address=0000
2022-06-07 08:40:52.770 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node 0000 is not updated
2022-06-07 08:40:52.774 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=02, status=SUCCESS, ieeeAddrRemoteDev=CCCCCCFFFEA5F359, nwkAddrRemoteDev=0000, startIndex=null, nwkAddrAssocDevList=[]]
2022-06-07 08:40:52.777 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=02, status=SUCCESS, ieeeAddrRemoteDev=CCCCCCFFFEA5F359, nwkAddrRemoteDev=0000, startIndex=null, nwkAddrAssocDevList=[]] 
2022-06-07 08:40:52.780 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0000, apsFrame=EmberApsFrame [profileId=0000, clusterId=0001, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B8], messageTag=02, status=EMBER_SUCCESS, messageContents=]
2022-06-07 08:40:52.781 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=899, state=COMPLETE, sendCnt=1, command=IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]]
2022-06-07 08:40:52.781 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for 0000 IeeeAddressRequest returned IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=02, status=SUCCESS, ieeeAddrRemoteDev=CCCCCCFFFEA5F359, nwkAddrRemoteDev=0000, startIndex=null, nwkAddrAssocDevList=[]]
2022-06-07 08:40:52.782 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=02 state=RX_ACK
2022-06-07 08:40:52.782 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2022-06-07 08:40:52.784 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=02, state=RX_ACK, outstanding=1
2022-06-07 08:40:52.784 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: transactionComplete, state=COMPLETE, outstanding=0
2022-06-07 08:40:52.792 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3
2022-06-07 08:40:52.798 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_BROADCAST, indexOrDestination=FFFC, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B5], messageTag=00, status=EMBER_SUCCESS, messageContents=]
2022-06-07 08:40:52.800 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=00 state=RX_ACK
2022-06-07 08:40:52.802 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=00, state=RX_ACK, outstanding=1
2022-06-07 08:40:52.805 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=1060, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=00, permitDuration=0, tcSignificance=true]]
2022-06-07 08:40:52.806 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2022-06-07 08:40:52.808 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=COMPLETE, outstanding=0
2022-06-07 08:40:52.809 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2022-06-07 08:40:52.811 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFC, TID=00, event=RX_ACK, state=COMPLETE
2022-06-07 08:40:53.880 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: running NODE_DESCRIPTOR
2022-06-07 08:40:53.884 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=1, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> 0000/0, cluster=0002, TID=--, nwkAddrOfInterest=0000]]
2022-06-07 08:40:53.886 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2022-06-07 08:40:53.888 [DEBUG] [transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=5, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> 0000/0, cluster=0002, TID=03, nwkAddrOfInterest=0000]]
2022-06-07 08:40:53.890 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2022-06-07 08:40:53.893 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0000/0 -> 0000/0, cluster=0002, TID=03, nwkAddrOfInterest=0000]
2022-06-07 08:40:53.895 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=03, rssi=--, lqi=--, payload=03 00 00]
2022-06-07 08:40:53.909 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BA]
2022-06-07 08:40:53.933 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0002, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BA], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=03 00 00]
2022-06-07 08:40:53.936 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BA, rssi=0, lqi=FF, payload=03 00 00]
2022-06-07 08:40:53.938 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node update. NWK Address=0000
2022-06-07 08:40:53.941 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node 0000 is not updated
2022-06-07 08:40:53.943 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NodeDescriptorRequest [0000/0 -> 0000/0, cluster=0002, TID=03, nwkAddrOfInterest=0000]
2022-06-07 08:40:53.946 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NodeDescriptorRequest [0000/0 -> 0000/0, cluster=0002, TID=03, nwkAddrOfInterest=0000] 
2022-06-07 08:40:53.949 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8002, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BB], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=03 00 00 00 00 40 8F CD AB 52 80 00 41 2C 80 00 00]
2022-06-07 08:40:53.953 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8002, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BB, rssi=0, lqi=FF, payload=03 00 00 00 00 40 8F CD AB 52 80 00 41 2C 80 00 00]
2022-06-07 08:40:53.955 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node update. NWK Address=0000
2022-06-07 08:40:53.958 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node 0000 is not updated
2022-06-07 08:40:53.965 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NodeDescriptorResponse [0000/0 -> 0000/0, cluster=8002, TID=03, status=SUCCESS, nwkAddrOfInterest=0000, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=82, complexDescriptorAvailable=false, manufacturerCode=ABCD, logicalType=COORDINATOR, serverCapabilities=[PRIMARY_TRUST_CENTER, NETWORK_MANAGER], incomingTransferSize=128, outgoingTransferSize=128, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[ALTERNATIVE_PAN, FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=22]]
2022-06-07 08:40:53.968 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NodeDescriptorResponse [0000/0 -> 0000/0, cluster=8002, TID=03, status=SUCCESS, nwkAddrOfInterest=0000, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=82, complexDescriptorAvailable=false, manufacturerCode=ABCD, logicalType=COORDINATOR, serverCapabilities=[PRIMARY_TRUST_CENTER, NETWORK_MANAGER], incomingTransferSize=128, outgoingTransferSize=128, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[ALTERNATIVE_PAN, FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=22]] 
2022-06-07 08:40:53.972 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=88, state=COMPLETE, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> 0000/0, cluster=0002, TID=03, nwkAddrOfInterest=0000]]
2022-06-07 08:40:53.972 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: NodeDescriptorResponse returned NodeDescriptorResponse [0000/0 -> 0000/0, cluster=8002, TID=03, status=SUCCESS, nwkAddrOfInterest=0000, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=82, complexDescriptorAvailable=false, manufacturerCode=ABCD, logicalType=COORDINATOR, serverCapabilities=[PRIMARY_TRUST_CENTER, NETWORK_MANAGER], incomingTransferSize=128, outgoingTransferSize=128, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[ALTERNATIVE_PAN, FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=22]]
2022-06-07 08:40:53.973 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2022-06-07 08:40:53.974 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: request NODE_DESCRIPTOR successful. Advancing to POWER_DESCRIPTOR.
2022-06-07 08:40:53.975 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: transactionComplete, state=COMPLETE, outstanding=0
2022-06-07 08:40:53.976 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0000, apsFrame=EmberApsFrame [profileId=0000, clusterId=0002, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BA], messageTag=03, status=EMBER_SUCCESS, messageContents=]
2022-06-07 08:40:53.977 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: running POWER_DESCRIPTOR
2022-06-07 08:40:53.977 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2022-06-07 08:40:53.978 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=03 state=RX_ACK
2022-06-07 08:40:53.980 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=03, state=RX_ACK, outstanding=0
2022-06-07 08:40:53.981 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0000/0 -> 0000/0, cluster=0003, TID=--, nwkAddrOfInterest=0000]]
2022-06-07 08:40:53.982 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2022-06-07 08:40:53.985 [DEBUG] [transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=5, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0000/0 -> 0000/0, cluster=0003, TID=04, nwkAddrOfInterest=0000]]
2022-06-07 08:40:53.987 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2022-06-07 08:40:53.989 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0000/0 -> 0000/0, cluster=0003, TID=04, nwkAddrOfInterest=0000]
2022-06-07 08:40:53.991 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=04, rssi=--, lqi=--, payload=04 00 00]
2022-06-07 08:40:54.005 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BC]
2022-06-07 08:40:54.028 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0003, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BC], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=04 00 00]
2022-06-07 08:40:54.031 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BC, rssi=0, lqi=FF, payload=04 00 00]
2022-06-07 08:40:54.034 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node update. NWK Address=0000
2022-06-07 08:40:54.036 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node 0000 is not updated
2022-06-07 08:40:54.039 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: PowerDescriptorRequest [0000/0 -> 0000/0, cluster=0003, TID=04, nwkAddrOfInterest=0000]
2022-06-07 08:40:54.042 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: PowerDescriptorRequest [0000/0 -> 0000/0, cluster=0003, TID=04, nwkAddrOfInterest=0000] 
2022-06-07 08:40:54.045 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8003, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BD], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=04 00 00 00 10 C1]
2022-06-07 08:40:54.048 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8003, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BD, rssi=0, lqi=FF, payload=04 00 00 00 10 C1]
2022-06-07 08:40:54.051 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node update. NWK Address=0000
2022-06-07 08:40:54.054 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node 0000 is not updated
2022-06-07 08:40:54.063 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: PowerDescriptorResponse [0000/0 -> 0000/0, cluster=8003, TID=04, status=SUCCESS, nwkAddrOfInterest=0000, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[MAINS], currentPowerSource=MAINS, powerLevel=FULL]]
2022-06-07 08:40:54.065 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: PowerDescriptorResponse [0000/0 -> 0000/0, cluster=8003, TID=04, status=SUCCESS, nwkAddrOfInterest=0000, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[MAINS], currentPowerSource=MAINS, powerLevel=FULL]] 
2022-06-07 08:40:54.069 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=89, state=COMPLETE, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 0000/0, cluster=0003, TID=04, nwkAddrOfInterest=0000]]
2022-06-07 08:40:54.069 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: PowerDescriptorResponse returned PowerDescriptorResponse [0000/0 -> 0000/0, cluster=8003, TID=04, status=SUCCESS, nwkAddrOfInterest=0000, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[MAINS], currentPowerSource=MAINS, powerLevel=FULL]]
2022-06-07 08:40:54.071 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2022-06-07 08:40:54.070 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0000, apsFrame=EmberApsFrame [profileId=0000, clusterId=0003, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BC], messageTag=04, status=EMBER_SUCCESS, messageContents=]
2022-06-07 08:40:54.071 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: request POWER_DESCRIPTOR successful. Advancing to null.
2022-06-07 08:40:54.072 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: transactionComplete, state=COMPLETE, outstanding=0
2022-06-07 08:40:54.073 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=04 state=RX_ACK
2022-06-07 08:40:54.074 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - CCCCCCFFFEA5F359: Node SVC Discovery: complete
2022-06-07 08:40:54.074 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2022-06-07 08:40:54.075 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=04, state=RX_ACK, outstanding=0
2022-06-07 08:40:54.077 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Updating node NWK=0000
2022-06-07 08:40:54.080 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node update. NWK Address=0000
2022-06-07 08:40:54.082 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - CCCCCCFFFEA5F359: Node descriptor updated
2022-06-07 08:40:54.084 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - CCCCCCFFFEA5F359: Power descriptor updated
2022-06-07 08:40:54.090 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
2022-06-07 08:40:54.091 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - CCCCCCFFFEA5F359: Data store: Deferring write for 250ms.
2022-06-07 08:40:54.092 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - CCCCCCFFFEA5F359: NodeDescriptor passed to Ember NCP NodeDescriptor [apsFlags=0, bufferSize=82, complexDescriptorAvailable=false, manufacturerCode=ABCD, logicalType=COORDINATOR, serverCapabilities=[PRIMARY_TRUST_CENTER, NETWORK_MANAGER], incomingTransferSize=128, outgoingTransferSize=128, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[ALTERNATIVE_PAN, FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=22]
2022-06-07 08:40:54.344 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - CCCCCCFFFEA5F359: Data store: Writing node.
2022-06-07 08:40:56.658 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - CCCCCCFFFEA5F359: ZigBee saving network state complete.

holy cow, lots of stuff going on there…
but towards the end of the log it seems all being OK…
The Ember coordinator is ONLINE
Phew…

(will report back shortly, after trying to connect the bulb)

Max_G · June 6, 2022, 11:25pm

OK, did one scan, and could see the coordinator opening a join window for 60 sec:

2022-06-07 09:11:23.147 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:42b78e1deb
2022-06-07 09:11:23.149 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to FFFC/0 for 60 seconds.
2022-06-07 09:11:23.151 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2022-06-07 09:11:23.153 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2022-06-07 09:11:23.155 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFC/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=4, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=03, permitDuration=60, tcSignificance=true]]
2022-06-07 09:11:23.157 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2022-06-07 09:11:23.159 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=03, permitDuration=60, tcSignificance=true]
2022-06-07 09:11:23.161 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFC/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=03, rssi=--, lqi=--, payload=03 3C 01]
2022-06-07 09:11:23.163 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2022-06-07 09:11:23.165 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2022-06-07 09:11:23.167 [DEBUG] [transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=4, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true]]
2022-06-07 09:11:23.169 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2022-06-07 09:11:23.171 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true]
2022-06-07 09:11:23.173 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=04, rssi=--, lqi=--, payload=04 3C 01]
2022-06-07 09:11:23.174 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [networkId=0, status=EMBER_SUCCESS, sequence=A3]
2022-06-07 09:11:23.195 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspStackStatusHandler [networkId=0, status=EMBER_NETWORK_OPENED]
2022-06-07 09:11:23.199 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=A3], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=03 3C 01]
2022-06-07 09:11:23.200 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=A4]
2022-06-07 09:11:23.202 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=A4], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=04 3C 01]
2022-06-07 09:11:23.204 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=A4, rssi=0, lqi=FF, payload=04 3C 01]
2022-06-07 09:11:23.206 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node update. NWK Address=0000
2022-06-07 09:11:23.208 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node 0000 is not updated
2022-06-07 09:11:23.210 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true]
2022-06-07 09:11:23.212 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true] 
2022-06-07 09:11:23.216 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=A5], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=04 80]
2022-06-07 09:11:23.217 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=A5, rssi=0, lqi=FF, payload=04 80]
2022-06-07 09:11:23.220 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node update. NWK Address=0000
2022-06-07 09:11:23.221 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F359: Node 0000 is not updated
2022-06-07 09:11:23.223 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=04, status=INV_REQUESTTYPE]
2022-06-07 09:11:23.225 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=04, status=INV_REQUESTTYPE] 
2022-06-07 09:11:23.228 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0000, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=A4], messageTag=04, status=EMBER_SUCCESS, messageContents=]
2022-06-07 09:11:23.230 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=04 state=RX_ACK
2022-06-07 09:11:23.231 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=04, state=RX_ACK, outstanding=2
2022-06-07 09:11:23.233 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=CCCCCCFFFEA5F359 queueTime=70, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true]]
2022-06-07 09:11:23.235 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2022-06-07 09:11:23.236 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - CCCCCCFFFEA5F359: transactionComplete, state=COMPLETE, outstanding=0
2022-06-07 09:11:23.238 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3
2022-06-07 09:11:23.239 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0000, TID=04, event=RX_ACK, state=COMPLETE
2022-06-07 09:11:24.124 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_BROADCAST, indexOrDestination=FFFC, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=A3], messageTag=03, status=EMBER_SUCCESS, messageContents=]
2022-06-07 09:11:24.126 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=03 state=RX_ACK
2022-06-07 09:11:24.127 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=03, state=RX_ACK, outstanding=1
2022-06-07 09:11:24.130 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=979, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=03, permitDuration=60, tcSignificance=true]]
2022-06-07 09:11:24.132 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2022-06-07 09:11:24.133 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=COMPLETE, outstanding=0
2022-06-07 09:11:24.135 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2022-06-07 09:11:24.136 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFC, TID=03, event=RX_ACK, state=COMPLETE
2022-06-07 09:12:23.084 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspStackStatusHandler [networkId=0, status=EMBER_NETWORK_CLOSED]

All I seem to be able to make out is:
it looks like there was an incoming transmission…
then something removed
closed…

Can’t really make sense of it…

Despite being unsure… it seems the coordinator is working…

In case it found the bulb, where would I find it?
I looked under Things, there is no bulb…

BTW: the docs say “look in your inbox” I cannot see/find an inbox in the UI.

I reckon it is time to get a Tradfri bulb …

chris · June 6, 2022, 11:33pm

I’m not completely sure what you refer to here, but there are no incoming transmissions and no devices were found by the coordinator.

I guess this is a bit old - the inbox is now part of the things screen in the new UI (it shows a red tag with the number of devices discovered next to the binding, and another button/box at the bottom of the things screen if I remember correctly).

Yes, it looks ok.

What I don’t know though is what you did with the device - did you reset this as suggested above? If not, it may not attempt to join the network - even if the network is open.

Max_G · June 6, 2022, 11:50pm

Thank you…

The bulb comes with minimum instructions to do the ON-OFF thing three times ending in ON.
Started ‘scan’ in the UI, and then switched the bulb.
… but by the looks of it and what you said, it did not join.

Max_G · June 7, 2022, 12:26pm

OK, I had bought 4 of these bulbs.
The one I tried was slightly flickering when on, so I considered it faulty, and used another one.
This one joined the coordinator.
Some 650 lines in the debug log (compared to scanning only (without something joining, which created some 50 lines of debug code))

I assume the default log level was info?!
So I set these like so:

openhab> log:set info com.zsmartsystems.zigbee
openhab> log:set info org.openhab.binding.zigbee

The next question is: How do I control the colour of the bulb?

Once scanning found the new bulb, I created a thing from it: “Smart Bulb 1”
I added a dimmer item and linked it with the Bulb thing.
I can dim the bulb (with the dimmer item in the UI)

How to control colour?

[edit 1] I found another item ‘color’, which I linked to the bulb as well.
But it does not have a colour wheel of sort.

Is there a sitemap I can display the controls for the bulb?

(I can’t believe having used OH for years and do not get OH3)

[edit 2] I saw the “child ageing timeout” in the Ember coordinator config.
I currently have this bulb connected to a power socket.
Is this correct: to prevent the bulb from being removed fro the coordinator, the bulb needs to be powered permanently?
Also, do I use the dimmer to switch off the bulb, by sliding the dimmer to 0?
Or do I need to add a switch item to the bulb as well?
If so, it would mean I need three items to control one light?!

chris · June 7, 2022, 8:14pm

Great - I’m glad it’s working.

This is a router - routers are mains powered while child devices are battery powered so this doesn’t impact the router.

The device will not be removed from the coordinator if it is not powered, but it can cause issues as routers in a zigbee network are expected to be powered and it may impact the mesh routing if you power it off. If it has child devices connected (eg battery devices) then they will likely become unreachable as well.

However when you power the device back on it should continue to work.

You can do either - or you can create a dimmer item, and attach a switch widget in the UI - it doesn’t require a separate item as dimmer items can take switches and slider commands. Likewise, a color item can take colour, slider/dimmer and switches, so you only need a single item.

No - just one item linked to the color channel and you can use a switch, a slider, or a color widget to control it as you desire - just configure this up in the UI. This is how OH has always worked - no change from older versions (ie since version 1 even).

Pedro_Liberal · June 7, 2022, 9:46pm

Great explanation.
We need more people creating YouTube tutorials… on that home assistant has us beat…

Max_G · June 8, 2022, 9:28am

As mentioned before, I cannot control colour after linking the channel with the item…
The reason seems to be this bug:

github.com/openhab/openhab-webui

[Main UI - Color Widgets] Widgets for Extended Color Lights are not shown

opened 09:02AM - 26 Feb 21 UTC

curlyel

bug main ui

## The problem Color items for newly discovered things (Extended Color Lights…) don't get any color widget shown in all parts of the Main UI. Eg.: ![image](https://user-images.githubusercontent.com/11849305/109276817-c7b3e000-7816-11eb-929a-5229269cc036.png The behaviour has been seen so far with lights discovered by the Deconz binding as well as by the Zigbee binding. For the Deconz binding some change seemed to solve the issue (see: https://github.com/openhab/openhab-addons/issues/10107#) I already opened an issue in the openhab-addon repository related to the Zigbee binding (see: https://github.com/openhab/openhab-addons/issues/10223) Although, @cdjackson as the maintainer of the Zigbee binding suspects the cause in the webui. Therefore I raise this issue here too to start the discussion if it is to be solved in the binding _or_ the webui. The following seem to support Chris's point of view: ``` openhab> send ZIGRGBWStripBuero_Color ON Command has been sent successfully. openhab> send ZIGRGBWStripBuero_Color 120,75,41 Command has been sent successfully. openhab> ``` Openhab accepts the ON/OFF as well as the color commands sent to the item. And the real device indeed updates the color. ## Expected behavior I'd expect a color widget show in standalone or lists allowing to control the color, e.g.: ![image](https://user-images.githubusercontent.com/11849305/109278514-e74c0800-7818-11eb-876e-a05913274f52.png) ## Steps to reproduce - discover extended color light by the Zigbee binding (maybe other binding are affected as well) - bind the color channel of the discovered light to a color item by "create equipment from thing" from within the model page - ## Your environment ```yaml runtimeInfo: version: 3.1.0.M1 buildString: Milestone Build locale: de_DE systemInfo: configFolder: /etc/openhab userdataFolder: /var/lib/openhab logFolder: /var/log/openhab javaVersion: 11.0.10 javaVendor: Azul Systems, Inc. javaVendorVersion: Zulu11.45+27-CA osName: Linux osVersion: 5.10.12-sunxi osArchitecture: arm availableProcessors: 4 freeMemory: 105461296 totalMemory: 323035136 bindings: - astro - bluetooth - harmonyhub - hue - knx - kodi - miio - mqtt - network - networkupstools - rfxcom - shelly - sonos - systeminfo - zigbee - zwave clientInfo: device: ios: false android: false androidChrome: false desktop: true iphone: false ipod: false ipad: false edge: false ie: false firefox: false macos: false windows: true cordova: false phonegap: false electron: false nwjs: false webView: false webview: false standalone: false os: windows pixelRatio: 1.25 prefersColorScheme: dark isSecureContext: false locationbarVisible: true menubarVisible: true navigator: cookieEnabled: true deviceMemory: N/A hardwareConcurrency: 8 language: de-DE languages: - de-DE - de - en-US - en onLine: true platform: Win32 screen: width: 3072 height: 1728 colorDepth: 24 support: touch: false pointerEvents: true observer: true passiveListener: true gestures: false intersectionObserver: true themeOptions: dark: light filled: true pageTransitionAnimation: default bars: filled homeNavbar: default homeBackground: default expandableCardAnimation: default userAgent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.182 Safari/537.36 timestamp: 2021-02-26T08:59:41.316Z ```