CHIP lighting demo, Commissioning starts, app dies, 52840dk seems to be in child state, but app does not control light on/off.

[riedlse]

Tried running android app in debug mode, but I could not see any data on the crash.

tried resetting the board a few time and re commissioning.

followed the guide to set up the DK board, AP (used a dongle instead of DK, but seems to be operational) and the android commissioning app.

uart:~$ ot ipaddr

fd11:22:0:0:9b0c:d235:7ee8:629c

fd58:94c1:25c8:62db:0:ff:fe00:a804

fd58:94c1:25c8:62db:97f9:1f55:2419:2566

fe80:0:0:0:98d0:439c:d01:8621

Done

uart:~$ ot state

child

Done

uart:~$ 

[riedlse]

Device says it's a child and has an IP address, but LED1 is still a short flash, so something not fully setup yet?

managed to grab the android studio debug log

D/CTL: Sending Thread credentials for channel 15, PAN ID 1234...
D/NP: Sending Thread Credentials
D/IN: Secure message was encrypted: Msg ID 0
Sending msg from 112233 to 12344321
Sending secure msg on connection specific transport
D/CTL: Received SendCharacteristic
Calling Java SendCharacteristic
D/IN: Secure msg send status 0
D/chip.BluetoothManager: ChipLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/CTL: Received SendCharacteristic
Calling Java SendCharacteristic
D/chip.BluetoothManager: ChipLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: ChipLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/CTL: Received SendCharacteristic
Calling Java SendCharacteristic
D/chip.BluetoothManager: ChipLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/CTL: Received SendCharacteristic
Calling Java SendCharacteristic
D/chip.BluetoothManager: ChipLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: ChipLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/CTL: Received SendCharacteristic
Calling Java SendCharacteristic
D/chip.BluetoothManager: ChipLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/CTL: Received SendCharacteristic
Calling Java SendCharacteristic
D/chip.BluetoothManager: ChipLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: ChipLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/CTL: Received SendCharacteristic
Calling Java SendCharacteristic
D/chip.BluetoothManager: ChipLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/CTL: Received SendCharacteristic
Calling Java SendCharacteristic
D/chip.BluetoothManager: ChipLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: ChipLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/chip.BluetoothManager: ChipLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/CTL: Received SendCharacteristic
Calling Java SendCharacteristic
D/chip.BluetoothManager: ChipLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: ChipLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/chip.BluetoothManager: ChipLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/CTL: Received SendCharacteristic
D/CTL: Calling Java SendCharacteristic
D/chip.BluetoothManager: ChipLight.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: ChipLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/chip.BluetoothManager: ChipLight.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/CTL: Received SendCharacteristic
Calling Java SendCharacteristic
D/NP: Received kIPAddressAssigned
D/CTL: Remote device was assigned an ip address
I/DeviceProvisioningFragment: Pairing status update: 2
W/e.chip.chiptoo: 0xebadde09 skipped times: 0
A/libc: Fatal signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x2000000a9 in tid 2024 (Binder:30144_3), pid 30144 (e.chip.chiptool)
D/Toast: show: focusDisplayId = 0, isFocusInDesktop = false mCustomDisplayId=-1
V/Toast: SHOW: android.widget.Toast$TN@f177170
Disconnected from the target VM, address: 'localhost:56965', transport: 'socket'

[riedlse]

So, further along, but still not quite there. It looks like I didn't understand that you needed to do all of the AP wifi setup on the border router (and the doc is missing some info about starting Dnsmasq and targa... but I think I got passed all of that. So I'm connected, the ombre shows the child in the map now. I can ping the border router. However seems something is still not working as after I hit the "Save Network", nothing happens (well it looks like the child gets setup correctly, but the screen on the chip tool never advances)

May still be some routing or Dnsmasq errors, but still at a bit of a loss....

on the child device I get

D: 305441[DL] Write request received for CHIPoBLE RX characteristic (ConnId 0x00)

D: 307949[DL] Sending indication for CHIPoBLE TX characteristic (ConnId 0, len 3)

D: 308050[DL] Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)

D: 310572[DL] Write request received for CHIPoBLE RX characteristic (ConnId 0x00)

D: 313080[DL] Sending indication for CHIPoBLE TX characteristic (ConnId 0, len 3)

D: 313182[DL] Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)

D: 315655[DL] Write request received for CHIPoBLE RX characteristic (ConnId 0x00)

D: 318164[DL] Sending indication for CHIPoBLE TX characteristic (ConnId 0, len 3)

D: 318265[DL] Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)

D: 320965[DL] Write request received for CHIPoBLE RX characteristic (ConnId 0x00)

D: 323472[DL] Sending indication for CHIPoBLE TX characteristic (ConnId 0, len 3)

D: 323575[DL] Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)

E: 338479[BLE] ack recv timeout, closing ep 0x20006c40

I: 338484[SVR] OnRendezvousError: Ble Error 6024 (0x00001788): Message fragment acknowledgement timed out

I: 338493[BLE] Releasing end point's BLE connection back to application.

D: 403448[DL] Write request received for CHIPoBLE RX characteristic (ConnId 0x00)

I: 403456[BLE] Releasing end point's BLE connection back to application.

E: 403462[BLE] HandleChipConnectionReceived failed, err = 6018

E: 403468[BLE] failed handle new chip BLE connection, status = 6018

D: 418478[DL] ConnId: 0x00, New CCCD value: 0x0000

E: 418483[BLE] no endpoint for unsub recvd

I: 419603[DL] BLE GAP connection terminated (reason 0x13)

I: 419608[DL] Current number of connections: 0/1

D: 419612[DL] In DriveBLEState

I: 419619[DL] CHIPoBLE advertising started

[kkasperczyk]

Hi riedlse, thanks for reporting an issue. WiFi AP is necessary in order to provide the mobile app Internet access within the known network and be able to route packets from that network to the Thread device through the border router. So generally we can divide this test process on the two stages:

• Commissioning (so called Rendezvous) - For that one you need existing Thread network (so running border router, which is Thread network leader), not configured CHIP device and smartphone running CHIP Tool mobile app. After scanning device's QR code the devices are starting exchanging information over BLE like encryption and session keys and etc. After that device has all information necessary to communicate using CHIP stack, but still is not attached to any network (Thread in that case). After that you see on the mobile app window asking to enter Thread network credentials, you press "Save network" button and CHIP device should receive it, configure Thread and join the border router's Thread network as a CHILD. All the communication is done using BLE, so for that part you don't need WiFi AP (however it's good to have it configured before, as described in the guide).
• Controlling - For that one you need WiFi AP, border router and configured routing on PC, as smartphone sends IPv6 packets using WiFi and is not able to reach device inside the Thread network directly. Packets are going to the PC wlan port, routed to the border router and then sent to the CHIP device.

The important thing is to detect on which stage is your test failing. Please note that CHIP is project in early development, so after reset CHIP device is not able to communicate with the smartphone even it was paired successfully before. Also pairing device multiple times, after it changes state to CHILD will not work either. If something is going wrong, it is good idea to do the device factory reset (pressing button nr 1 for over 6 seconds), check if Thread is disabled and start pairing from the beginning.

To help me solve your problem, I would like to ask you to answer few questions:

• Do you use output .hex and .apk files attached to the blog post or you tried to build apps on your own? I'm asking because you wrote that problem is with CHIP lighting demo, while attached application is lock-app, so I would like to just clarify it. 
• Can you find in the device logs messages similar to the following:

I: 135225[IN] New pairing for device lu, key 0!!
I: 135230[SVR] Received a new connection.
I: 135234[SVR] Device completed SPAKE2+ handshake

?

It should appear just before displaying Thread network configuration window on the mobile app and it proves that rendezvous session was completed successfully.

• Do you see on the CHIP device logs after pressing on the mobile app "Save network" button that it changed state to CHILD? I'm a bit confused, because you attached logs showing that after exchanging CHIPoBLE TX/RX characteristics connection is broken, so operation failed, but you also wrote that it goes to the CHILD state, so I'm not sure how did you achieve it? Was there a further log saying that it changed state to CHILD or you had device in the CHILD state after previous session and you tried to pair it once again? In case you did - it will not work, so you could try factory reset the device to disable Thread and pair it once again.

When making any further tests, please try to capture and provide as much logs from the nrf52840DK as you can - it will definitely help to find the problem.

In my opinion you have some problems with completing commissioning stage successfully and routing doesn't have much to do with it, as all information are exchanged over BLE. But if it comes to the possible further routing issues, you can also try to investigate it. After having device in the CHILD state you may try to get its ip address, by typing `ot ipaddr`, as you did before, and ping it from your PC terminal. If you manage to do that, it will mean that routing is working fine. Pinging border router from the CHIP device will not check it, as they are inside of the same Thread network with the parent-child relation, so they should be able to communicate even without any routing settings.

[riedlse]

Yes, I am definitely using the light demo (I think the lock demo is essentially the same as the light demo)

OK, getting long here, definitely some issues with the border router, still not 100% certain it is setup correctly, but I do get farther. tried docker version, but that doesn't give you the AP, so went back and found stretch lite and reloaded. wifi setup didn't work (again and manually went through the setup) But I think something is still not quite there in routing? dnsmasq, tayga and bind9 (and all the other otbr processes seem to be there)

the device seems to be provisioned correctly per the thread below, an to state says it's a child, but I am back to the led short flash that says it is unprovisioned? Although it is clearly on the network? Although the topology on the OTBR does not show it.

uart:~$ ot state

child

Done

uart:~$ ot ipaddr

fd11:22:0:0:f113:838d:7249:27e2

fd2b:2ba5:d5b:b65f:0:ff:fe00:2801

fd2b:2ba5:d5b:b65f:2cc8:eacc:3c66:15e5

fe80:0:0:0:f02c:3c0:e45c:b68f

Done

uart:~$ ot ping fd2b:2ba5:d5b:b65f:4ade:bb00:8852:eee1

Done

16 bytes from fd2b:2ba5:d5b:b65f:4ade:bb00:8852:eee1: icmp_seq=1 hlim=64 time=27ms

uart:~$ 

The chiptool gets a 

chip.devicecontroller.ChipDeviceControllerException: OS Error 2101 Network is unreachable

Scroll to bottom, I tried using button 3 to connect to the network, seems to connect but gets errors as well.

I: 26608[BLE] Received rendezvous message for lu

I: 26612[BLE] Received rendezvous message from lu

I: 26617[NP] Received kThreadAssociationRequest

I: 26635[SVR] Device was assigned network credentials

I: 26640[DIS] CHIP minimal mDNS started advertising.

I: 26645[SVR] Device completed Rendezvous process

D: 26650[DL] In DriveBLEState

D: 26654[DL] OpenThread State Changed (Flags: 0x0106d01d)

D: 26659[DL]    Device Role: DETACHED

D: 26663[DL]    Network Name: OpenThread

D: 26666[DL]    PAN Id: 0x1234

D: 26669[DL]    Extended PAN Id: 0x1111111122222222

D: 26674[DL]    Channel: 15

D: 26676[DL]    Mesh Prefix: fdde:ad00:beef::/64

D: 26681[DL]    Thread Unicast Addresses:

D: 26685[DL]         fdde:ad00:beef:0:2cc8:eacc:3c66:15e5/64 valid preferred

D: 26691[DL]         fe80::f02c:3c0:e45c:b68f/64 valid preferred

D: 29081[DL] OpenThread State Changed (Flags: 0x001132b7)

D: 29086[DL]    Device Role: CHILD

D: 29089[DL]    Network Name: OpenThreadDemo

D: 29093[DL]    PAN Id: 0x1234

D: 29096[DL]    Extended PAN Id: 0x1111111122222222

D: 29101[DL]    Channel: 15

D: 29103[DL]    Mesh Prefix: fd2b:2ba5:d5b:b65f::/64

D: 29108[DL]    Partition Id: 0x7C04DEE2

D: 29112[DL]    Thread Unicast Addresses:

D: 29115[DL]         fd11:22::f113:838d:7249:27e2/64 valid preferred

D: 29122[DL]         fd2b:2ba5:d5b:b65f:0:ff:fe00:2801/64 valid preferred rloc

D: 29129[DL]         fd2b:2ba5:d5b:b65f:2cc8:eacc:3c66:15e5/64 valid preferred

D: 29136[DL]         fe80::f02c:3c0:e45c:b68f/64 valid preferred

I: 29141[NP] Sending IP Address. Delegate 0x20005b34

D: 29147[IN] Secure message was encrypted: Msg ID 0

I: 29151[IN] Sending msg from lu to lu

I: 29155[IN] Sending secure msg on connection specific transport

D: 29161[DL] Sending indication for CHIPoBLE TX characteristic (ConnId 0, len 20)

I: 29168[IN] Secure msg send status 0

D: 29171[DL] OpenThread State Changed (Flags: 0x00000001)

D: 29177[DL]    Thread Unicast Addresses:

D: 29180[DL]         fd11:22::f113:838d:7249:27e2/64 valid preferred

D: 29186[DL]         fd2b:2ba5:d5b:b65f:0:ff:fe00:2801/64 valid preferred rloc

D: 29193[DL]         fd2b:2ba5:d5b:b65f:2cc8:eacc:3c66:15e5/64 valid preferred

D: 29200[DL]         fe80::f02c:3c0:e45c:b68f/64 valid preferred

I: 29206[NP] Sending IP Address. Delegate 0x20005b34

D: 29212[IN] Secure message was encrypted: Msg ID 1

I: 29216[IN] Sending msg from lu to lu

I: 29220[IN] Sending secure msg on connection specific transport

I: 29226[IN] Secure msg send status 0

D: 29234[DL] Write request received for CHIPoBLE RX characteristic (ConnId 0x00)

D: 29292[DL] Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)

D: 29300[DL] Sending indication for CHIPoBLE TX characteristic (ConnId 0, len 20)

D: 29385[DL] Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)

D: 29393[DL] Write request received for CHIPoBLE RX characteristic (ConnId 0x00)

D: 29400[DL] Sending indication for CHIPoBLE TX characteristic (ConnId 0, len 20)

D: 29472[DL] Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)

D: 29480[DL] Sending indication for CHIPoBLE TX characteristic (ConnId 0, len 20)

D: 29565[DL] Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)

D: 29573[DL] Write request received for CHIPoBLE RX characteristic (ConnId 0x00)

D: 29580[DL] Sending indication for CHIPoBLE TX characteristic (ConnId 0, len 12)

D: 29652[DL] Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)

D: 29660[DL] Sending indication for CHIPoBLE TX characteristic (ConnId 0, len 20)

D: 29744[DL] Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)

I: 30732[DL] BLE GAP connection terminated (reason 0x13)

I: 30737[SVR] OnRendezvousError: Ble Error 6012 (0x0000177C): Remote device closed BLE connection

I: 30746[DL] Current number of connections: 0/1

D: 30750[DL] In DriveBLEState

I: 30758[DL] CHIPoBLE advertising started

>>>>> When reset then hit button 3

I: 502[DL] OpenThread started: OK

I: 505[DL] Setting OpenThread device type to MINIMAL END DEVICE

I: 511[ZCL] deactivate report event

I: 515[ZCL] Cluster callback: 6

I: 517[ZCL] Cluster callback: 8

I: 520[ZCL] Value: 255, length 1

I: 523[ZCL] sched report event in 65343477 ms

D: 528[IN] TransportMgr initialized

I: 531[IN] local node id is lu

D: 534[BLE] Waiting for PBKDF param request

I: 538[SVR] Server Listening...

I: 541[DL] Device Configuration:

I: 544[DL]   Serial Number: (not set)

I: 547[DL]   Vendor Id: 9050 (0x235A)

I: 550[DL]   Product Id: 65279 (0xFEFF)

I: 554[DL]   Product Revision: 1

I: 557[DL]   Setup Pin Code: 12345678

I: 560[DL]   Setup Discriminator: 3840 (0xF00)

I: 565[DL]   Manufacturing Date: (not set)

I: 569[SVR] SetupQRCode:  [CH:I34DV*-00 0C9SS0]

I: 573[SVR] Copy/paste the below URL in a browser to see the QR Code:

I: 579[SVR] dhrishi.github.io/.../qrcode.html

D: 588[DL] CHIP task running

D: 590[DL] In DriveBLEState

I: Device is not commissioned to a Thread network. Starting with the default configuration.

I: 6982[DL] CHIPoBLE advertising disabled because device is fully provisioned

D: 6989[DL] In DriveBLEState

I: 6992[SVR] nfc_t2t_emulation_stop failed: -35

E: Stopping NFC Tag emulation failed

D: 6999[DL] OpenThread State Changed (Flags: 0x0106d01d)

D: 7004[DL]    Device Role: DETACHED

D: 7008[DL]    Network Name: OpenThread

D: 7011[DL]    PAN Id: 0x1234

D: 7014[DL]    Extended PAN Id: 0x1111111122222222

D: 7019[DL]    Channel: 15

D: 7021[DL]    Mesh Prefix: fd11:1111:1122::/64

D: 7025[DL]    Thread Unicast Addresses:

D: 7029[DL]         fd11:1111:1122:0:eb54:5c65:358a:55b/64 valid preferred

D: 7036[DL]         fe80::e07f:da9f:829a:124/64 valid preferred

D: 9223[DL] OpenThread State Changed (Flags: 0x001132b7)

D: 9228[DL]    Device Role: CHILD

D: 9231[DL]    Network Name: OpenThreadDemo

D: 9235[DL]    PAN Id: 0x1234

D: 9238[DL]    Extended PAN Id: 0x1111111122222222

D: 9242[DL]    Channel: 15

D: 9245[DL]    Mesh Prefix: fd2b:2ba5:d5b:b65f::/64

D: 9249[DL]    Partition Id: 0x7C04DEE2

D: 9253[DL]    Thread Unicast Addresses:

D: 9257[DL]         fd11:22::474d:13cf:321:d9c6/64 valid preferred

D: 9263[DL]         fd2b:2ba5:d5b:b65f:0:ff:fe00:2803/64 valid preferred rloc

D: 9270[DL]         fd2b:2ba5:d5b:b65f:eb54:5c65:358a:55b/64 valid preferred

D: 9276[DL]         fe80::e07f:da9f:829a:124/64 valid preferred

I: 9282[NP] Sending IP Address. Delegate 0x20005b34

E: 9287[NP] Failed in sending IP address. error Error 4003 (0x00000FA3)

D: 9294[DL] OpenThread State Changed (Flags: 0x00000001)

D: 9299[DL]    Thread Unicast Addresses:

D: 9302[DL]         fd11:22::474d:13cf:321:d9c6/64 valid preferred

D: 9308[DL]         fd2b:2ba5:d5b:b65f:0:ff:fe00:2803/64 valid preferred rloc

D: 9315[DL]         fd2b:2ba5:d5b:b65f:eb54:5c65:358a:55b/64 valid preferred

D: 9322[DL]         fe80::e07f:da9f:829a:124/64 valid preferred

I: 9328[NP] Sending IP Address. Delegate 0x20005b34

E: 9332[NP] Failed in sending IP address. error Error 4003 (0x00000FA3)

ot state

child

Done

uart:~$ 

[riedlse]

Oh, I followed the build instruction and built the app and android app from scratch. I didn't notice the .hex files?