search

zsmartsystems / com.zsmartsystems.zigbee.sniffer

ZigBee sniffer using Ember NCP and routing packets to Wireshark for display
Eclipse Public License 1.0
33 stars 18 forks source link

Sonoff / ITead EFR32 Stick works sniffing but not with ZHA or z2m #26

Closed walthowd closed 3 years ago

walthowd commented 3 years ago

Hi Chris! This is a weird one, feel free to close/ignore if you are busy!

We are attempting to test the new Sonoff / ITead EFR32 stick with Home Assistant under ZHA and zigbee2mqtt.

https://www.itead.cc/zigbee-3-0-usb-dongle.html

In both ZHA and z2m, the sonoff radio appears to be unable to hear/process/receive any frames from any joining device. Running in verbose logging, the network gets opened for joining but no beacons, join requests, anything is ever logged as received.

There has been some talk that the EFR32 onboard may be frequency mis-tuned and Sonoff has released a new firmware to fix the issue with CTUNE set to 128. However, that doesn't seem to help at all.

https://github.com/xsp1989/zigbeeFirmware/issues/4

What is weird, is your sniffer application seems to work with the out of the box firmware and the updated tuned firmware. I can sniff my production network on channel 15 and see all traffic, all with reasonable LQI/RSSI values. 

java -jar ZigBeeSniffer.jar -port /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 -c 15 -baud 115200 -flow software
Z-Smart Systems Ember Packet Sniffer
NCP initialisation starting...
Opened serial port /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200
DEBUG  12:25:58.655  Opening port /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud with FLOWCONTROL_OUT_XONOFF.
DEBUG  12:25:58.666  ASH: Connect
DEBUG  12:25:58.666  AshFrameHandler thread started
DEBUG  12:25:58.666  ASH: Reconnect
DEBUG  12:25:58.667  --> TX ASH frame: AshFrameRst []
DEBUG  12:25:58.670  <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=6, reTx=false, data=05 90 01 8E 00 FF EA 0C 63 88 21 78 E2 00 00 FB C6 04 DC 3D]
DEBUG  12:25:58.670  ASH: Frame out of sequence - expected 0, received 6
DEBUG  12:25:58.672  <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=6, reTx=false, data=05 90 01 8E 00 FF DC 05 02 00 21 33 85]
DEBUG  12:25:58.672  ASH: Frame out of sequence - expected 0, received 7
DEBUG  12:25:58.716  TX EZSP: EzspVersionRequest [networkId=0, desiredProtocolVersion=4]
DEBUG  12:25:58.716  ASH: TX EZSP queue size: 1
DEBUG  12:25:59.768  <-- RX ASH frame: AshFrameRstAck [version=2, resetCode=11, Reset: Software]
DEBUG  12:26:01.019  ASH: Connected
DEBUG  12:26:01.020  Ember: Link State change to true, initialised=false, networkStateUp=false
DEBUG  12:26:01.020  Ember: Link State change to true ignored.
DEBUG  12:26:01.021  --> TX ASH frame: AshFrameData [frmNum=0, ackNum=0, reTx=false, data=00 00 00 04]
DEBUG  12:26:01.028  <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=1, reTx=false, data=00 80 00 08 02 90 67]
DEBUG  12:26:01.029  ASH: Frame acked and removed AshFrameData [frmNum=0, ackNum=0, reTx=false, data=00 00 00 04]
DEBUG  12:26:01.032  RX EZSP: EzspVersionResponse [networkId=0, protocolVersion=8, stackType=2, stackVersion=6790]
DEBUG  12:26:01.032  EzspVersionResponse [networkId=0, protocolVersion=8, stackType=2, stackVersion=6790]
DEBUG  12:26:01.033  --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]
DEBUG  12:26:01.033  TX EZSP: EzspVersionRequest [networkId=0, desiredProtocolVersion=8]
DEBUG  12:26:01.033  ASH: TX EZSP queue size: 1
DEBUG  12:26:01.034  --> TX ASH frame: AshFrameData [frmNum=1, ackNum=1, reTx=false, data=01 00 01 00 00 08]
DEBUG  12:26:01.040  <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=2, reTx=false, data=01 80 01 00 00 08 02 90 67]
DEBUG  12:26:01.040  ASH: Frame acked and removed AshFrameData [frmNum=1, ackNum=1, reTx=false, data=01 00 01 00 00 08]
DEBUG  12:26:01.041  RX EZSP: EzspVersionResponse [networkId=0, protocolVersion=8, stackType=2, stackVersion=6790]
DEBUG  12:26:01.041  EzspVersionResponse [networkId=0, protocolVersion=8, stackType=2, stackVersion=6790]
DEBUG  12:26:01.041  --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]
DEBUG  12:26:01.041  EzspVersionResponse [networkId=0, protocolVersion=8, stackType=2, stackVersion=6790]
DEBUG  12:26:01.041  TX EZSP: EzspGetStandaloneBootloaderVersionPlatMicroPhyRequest []
DEBUG  12:26:01.042  ASH: TX EZSP queue size: 1
DEBUG  12:26:01.042  --> TX ASH frame: AshFrameData [frmNum=2, ackNum=2, reTx=false, data=02 00 01 91 00]
DEBUG  12:26:01.047  <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=3, reTx=false, data=02 80 01 91 00 02 19 04 18 0F]
DEBUG  12:26:01.048  ASH: Frame acked and removed AshFrameData [frmNum=2, ackNum=2, reTx=false, data=02 00 01 91 00]
DEBUG  12:26:01.048  RX EZSP: EzspGetStandaloneBootloaderVersionPlatMicroPhyResponse [networkId=0, bootloaderVersion=1902, nodePlat=4, nodeMicro=24, nodePhy=15]
DEBUG  12:26:01.048  --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]
Ember NCP version     : 6.7.9.0
DEBUG  12:26:01.051  TX EZSP: EzspGetEui64Request []
DEBUG  12:26:01.051  ASH: TX EZSP queue size: 1
DEBUG  12:26:01.052  --> TX ASH frame: AshFrameData [frmNum=3, ackNum=3, reTx=false, data=03 00 01 26 00]
DEBUG  12:26:01.057  <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=4, reTx=false, data=03 80 01 26 00 60 A6 C9 FE FF 27 71 84]
DEBUG  12:26:01.057  ASH: Frame acked and removed AshFrameData [frmNum=3, ackNum=3, reTx=false, data=03 00 01 26 00]
Ember NCP EUI         : 847127FFFEC9A660
DEBUG  12:26:01.058  RX EZSP: EzspGetEui64Response [networkId=0, eui64=847127FFFEC9A660]
DEBUG  12:26:01.058  --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]
DEBUG  12:26:01.058  TX EZSP: EzspMfglibStartRequest [networkId=0, rxCallback=true]
DEBUG  12:26:01.058  ASH: TX EZSP queue size: 1
DEBUG  12:26:01.059  --> TX ASH frame: AshFrameData [frmNum=4, ackNum=4, reTx=false, data=04 00 01 83 00 01]
DEBUG  12:26:01.063  <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=5, reTx=false, data=04 80 01 83 00 00]
DEBUG  12:26:01.063  ASH: Frame acked and removed AshFrameData [frmNum=4, ackNum=4, reTx=false, data=04 00 01 83 00 01]
DEBUG  12:26:01.065  RX EZSP: EzspMfglibStartResponse [networkId=0, status=EMBER_SUCCESS]
DEBUG  12:26:01.065  --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]
DEBUG  12:26:01.065  EzspMfglibStartResponse [networkId=0, status=EMBER_SUCCESS]
DEBUG  12:26:01.066  TX EZSP: EzspMfglibSetChannelRequest [networkId=0, channel=15]
DEBUG  12:26:01.066  ASH: TX EZSP queue size: 1
DEBUG  12:26:01.066  --> TX ASH frame: AshFrameData [frmNum=5, ackNum=5, reTx=false, data=05 00 01 8A 00 0F]
DEBUG  12:26:01.071  <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=6, reTx=false, data=05 80 01 8A 00 00]
DEBUG  12:26:01.071  ASH: Frame acked and removed AshFrameData [frmNum=5, ackNum=5, reTx=false, data=05 00 01 8A 00 0F]
DEBUG  12:26:01.071  RX EZSP: EzspMfglibSetChannelResponse [networkId=0, status=EMBER_SUCCESS]
DEBUG  12:26:01.071  --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]
DEBUG  12:26:01.071  EzspMfglibSetChannelResponse [networkId=0, status=EMBER_SUCCESS]
NCP initialisation complete...
Wireshark destination : /127.0.0.1:17754
Logging on channel    : 15
No device ID set. Last 16 bits of device EUID will be used.
DEBUG  12:26:01.161  <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=6, reTx=false, data=05 90 01 8E 00 B8 CA 0C 63 88 9A 78 E2 4A 5D 5A 81 04 AC 31]
DEBUG  12:26:01.163  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=184, rssi=-54, packetContents=63 88 9A 78 E2 4A 5D 5A 81 04 AC 31]
WiresharkZepFrame [sequence=00000000, lqi=184, rssi=-54, data={63 88 9A 78 E2 4A 5D 5A 81 04 AC 31}]
DEBUG  12:26:01.170  --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]
DEBUG  12:26:01.791  <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=6, reTx=false, data=05 90 01 8E 00 A8 C6 05 02 00 AC DE DA]
DEBUG  12:26:01.792  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=168, rssi=-58, packetContents=02 00 AC DE DA]
WiresharkZepFrame [sequence=00000001, lqi=168, rssi=-58, data={02 00 AC DE DA}]
DEBUG  12:26:01.793  --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]
DEBUG  12:26:01.808  <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=6, reTx=false, data=05 90 01 8E 00 A0 C4 41 61 88 9F 78 E2 7E 1C 66 BB 48 02 00 00 AB B0 1D E9 28 C4 C8 36 00 83 B9 69 FE FF 57 B4 14 00 23 5D 45 D4 BA CE 2A E2 21 5D 2D 47 44 F7 BA F0 74 EB 26 45 87 B8 92 37 DA 19 92 A0 51 E9 BB 2A AA 4A]
DEBUG  12:26:01.819  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=160, rssi=-60, packetContents=61 88 9F 78 E2 7E 1C 66 BB 48 02 00 00 AB B0 1D E9 28 C4 C8 36 00 83 B9 69 FE FF 57 B4 14 00 23 5D 45 D4 BA CE 2A E2 21 5D 2D 47 44 F7 BA F0 74 EB 26 45 87 B8 92 37 DA 19 92 A0 51 E9 BB 2A AA 4A]
WiresharkZepFrame [sequence=00000002, lqi=160, rssi=-60, data={61 88 9F 78 E2 7E 1C 66 BB 48 02 00 00 AB B0 1D E9 28 C4 C8 36 00 83 B9 69 FE FF 57 B4 14 00 23 5D 45 D4 BA CE 2A E2 21 5D 2D 47 44 F7 BA F0 74 EB 26 45 87 B8 92 37 DA 19 92 A0 51 E9 BB 2A AA 4A}]
DEBUG  12:26:01.828  --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]
DEBUG  12:26:01.833  <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=6, reTx=false, data=05 90 01 8E 00 FF DC 05 02 00 75 92 91]
DEBUG  12:26:01.834  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=255, rssi=-36, packetContents=02 00 75 92 91]
WiresharkZepFrame [sequence=00000003, lqi=255, rssi=-36, data={02 00 75 92 91}]
DEBUG  12:26:01.836  --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]
DEBUG  12:26:01.846  <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=6, reTx=false, data=05 90 01 8E 00 FF DC 05 02 00 75 92 91]
DEBUG  12:26:01.847  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=255, rssi=-36, packetContents=02 00 75 92 91]
WiresharkZepFrame [sequence=00000004, lqi=255, rssi=-36, data={02 00 75 92 91}]
DEBUG  12:26:01.849  --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]
DEBUG  12:26:01.860  <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=6, reTx=false, data=05 90 01 8E 00 FF DC 33 61 88 DE 78 E2 7E 1C 00 00 48 06 AB B0 00 00 0F 49 02 01 66 BB 7E 1C 28 B3 4C 5B 04 A8 70 FF 0A 00 6F 0D 00 00 49 51 30 1B 24 6F 5B 35 3F 96 60 98 73 8E]
DEBUG  12:26:01.863  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=255, rssi=-36, packetContents=61 88 DE 78 E2 7E 1C 00 00 48 06 AB B0 00 00 0F 49 02 01 66 BB 7E 1C 28 B3 4C 5B 04 A8 70 FF 0A 00 6F 0D 00 00 49 51 30 1B 24 6F 5B 35 3F 96 60 98 73 8E]
WiresharkZepFrame [sequence=00000005, lqi=255, rssi=-36, data={61 88 DE 78 E2 7E 1C 00 00 48 06 AB B0 00 00 0F 49 02 01 66 BB 7E 1C 28 B3 4C 5B 04 A8 70 FF 0A 00 6F 0D 00 00 49 51 30 1B 24 6F 5B 35 3F 96 60 98 73 8E}]
DEBUG  12:26:01.867  --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]
DEBUG  12:26:01.869  <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=6, reTx=false, data=05 90 01 8E 00 A8 C6 05 02 00 76 09 A3]
DEBUG  12:26:01.870  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=168, rssi=-58, packetContents=02 00 76 09 A3]
WiresharkZepFrame [sequence=00000006, lqi=168, rssi=-58, data={02 00 76 09 A3}]
DEBUG  12:26:01.871  --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]
DEBUG  12:26:01.884  <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=6, reTx=false, data=05 90 01 8E 00 A4 C5 0C 63 88 A9 78 E2 00 00 8E 9D 04 B8 55]
DEBUG  12:26:01.885  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=164, rssi=-59, packetContents=63 88 A9 78 E2 00 00 8E 9D 04 B8 55]
WiresharkZepFrame [sequence=00000007, lqi=164, rssi=-59, data={63 88 A9 78 E2 00 00 8E 9D 04 B8 55}]
DEBUG  12:26:01.885  --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]
DEBUG  12:26:01.887  <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=6, reTx=false, data=05 90 01 8E 00 FF DC 05 02 00 A9 73 8D]
DEBUG  12:26:01.888  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=255, rssi=-36, packetContents=02 00 A9 73 8D]
WiresharkZepFrame [sequence=00000008, lqi=255, rssi=-36, data={02 00 A9 73 8D}]
DEBUG  12:26:01.888  --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]
DEBUG  12:26:02.036  <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=6, reTx=false, data=05 90 01 8E 00 9C C3 0C 63 88 AD 78 E2 66 BB AB B0 04 09 D1]
DEBUG  12:26:02.036  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=156, rssi=-61, packetContents=63 88 AD 78 E2 66 BB AB B0 04 09 D1]
WiresharkZepFrame [sequence=00000009, lqi=156, rssi=-61, data={63 88 AD 78 E2 66 BB AB B0 04 09 D1}]
DEBUG  12:26:02.036  --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]
DEBUG  12:26:02.039  <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=6, reTx=false, data=05 90 01 8E 00 A8 C6 05 12 00 AD C2 4E]
DEBUG  12:26:02.039  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=168, rssi=-58, packetContents=12 00 AD C2 4E]
WiresharkZepFrame [sequence=0000000A, lqi=168, rssi=-58, data={12 00 AD C2 4E}]
DEBUG  12:26:02.040  --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]
DEBUG  12:26:02.046  <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=6, reTx=false, data=05 90 01 8E 00 B4 C9 2D 61 88 A0 78 E2 AB B0 66 BB 48 02 AB B0 00 00 0D 49 28 C5 C8 36 00 83 B9 69 FE FF 57 B4 14 00 AA EB BA C3 39 DC B4 A2 23 5E 1E 7E F6 5F]
DEBUG  12:26:02.047  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=180, rssi=-55, packetContents=61 88 A0 78 E2 AB B0 66 BB 48 02 AB B0 00 00 0D 49 28 C5 C8 36 00 83 B9 69 FE FF 57 B4 14 00 AA EB BA C3 39 DC B4 A2 23 5E 1E 7E F6 5F]
WiresharkZepFrame [sequence=0000000B, lqi=180, rssi=-55, data={61 88 A0 78 E2 AB B0 66 BB 48 02 AB B0 00 00 0D 49 28 C5 C8 36 00 83 B9 69 FE FF 57 B4 14 00 AA EB BA C3 39 DC B4 A2 23 5E 1E 7E F6 5F}]
DEBUG  12:26:02.047  --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]
DEBUG  12:26:02.048  <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=6, reTx=false, data=05 90 01 8E 00 A8 C6 05 02 00 A0 B2 10]
DEBUG  12:26:02.048  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=168, rssi=-58, packetContents=02 00 A0 B2 10]
WiresharkZepFrame [sequence=0000000C, lqi=168, rssi=-58, data={02 00 A0 B2 10}]
DEBUG  12:26:02.049  --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]
DEBUG  12:26:02.286  <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=6, reTx=false, data=05 90 01 8E 00 A4 C5 0C 63 88 AE 78 E2 66 BB AB B0 04 D9 5B]
DEBUG  12:26:02.287  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=164, rssi=-59, packetContents=63 88 AE 78 E2 66 BB AB B0 04 D9 5B]
WiresharkZepFrame [sequence=0000000D, lqi=164, rssi=-59, data={63 88 AE 78 E2 66 BB AB B0 04 D9 5B}]
DEBUG  12:26:02.288  --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]
DEBUG  12:26:02.289  <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=6, reTx=false, data=05 90 01 8E 00 AC C7 05 02 00 AE CC F9]
DEBUG  12:26:02.290  RX EZSP: EzspMfglibRxHandler [networkId=0, linkQuality=172, rssi=-57, packetContents=02 00 AE CC F9]
WiresharkZepFrame [sequence=0000000E, lqi=172, rssi=-57, data={02 00 AE CC F9}]
DEBUG  12:26:02.290  --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]

Any ideas? Is there any option for initializing the NCP in a different way that perhaps ZHA or z2m is missing?

Really at a loss on this one.

cdjackson commented 3 years ago

Hi, I'm not really sure why this would do what you're describing. Firstly, I'm a little surprised that you need to change CTUNE - I've never done that with any customers etc (which have produced thousands of devices), and as I understand this is factory tuned so unless it is changed, I wouldn't have thought it should need setting again.

This library just uses the library at https://github.com/zsmartsystems/com.zsmartsystems.zigbee. I can't really answer if this does anything differently than what the other applications are doing though, since I don't know those applications. The sniffer does a basic startup of the NCP, then puts it into MFGLIB mode which allows it to receive all traffic, so that will definitely be different to how an application would use it since the MFGLIB is normally used for testing (eg for certification).

Sorry - I'm probably not so helpful.

Chris

walthowd commented 3 years ago

Thanks Chris for the insight. Just not sure on this one. I put the Sonoff stick back into pairing mode with ZHA on channel 25 and sniffed with another non-sonoff EZSP adapter on channel 25.

I attempted to join a single zigbee bulb and could see it's beacon requests on 25, but nothing transmitted from the sonoff in coordinator mode. Truly weird. Some low level hardware or firmware bug it seems.

Thanks again!