Hi Abhay,
On Fri, 2019-12-13 at 22:21 +0530, Abhay Agarwal wrote:
> Hi Inga
>
> On Thu, Dec 12, 2019 at 11:15 PM Stotland, Inga <
> inga.stotland@xxxxxxxxx
> > wrote:
> > Hi Abhay,
> >
> > On Thu, 2019-12-12 at 07:10 -0800, Inga Stotland wrote:
> >
> > Hi Abhay,
> >
> > On Thu, 2019-12-12 at 14:51 +0530, Abhay Agarwal wrote:
> >
> > Hi Inga
> >
> > On Tuesday, December 10, 2019, Stotland, Inga <
> > inga.stotland@xxxxxxxxx
> > > wrote:
> >
> > Hi Abhay,
> >
> > On Tue, 2019-12-10 at 18:20 +0530, Abhay Agarwal wrote:
> > > Hi Inga
> > >
> > >
> > > Thanks for the reply
> > >
> > > Unfortunately we are still not able to resolve the issue
> > >
> > > We have used following mesh-cfgclient commands
> > >
> > >
> > > [mesh-cfgclient]# create
> > >
> > > [mesh-cfgclient]# appkey-create 0000 0001
> > >
> > > [mesh-cfgclient]# discover-unprovisioned on
> > >
> > > Unprovisioned scan started
> > >
> > > Scan result:
> > >
> > > rssi = -62
> > >
> > > UUID = F24B3F329DF200000000000000000000
> > >
> > >
> > > [mesh-cfgclient]# provision F24B3F329DF200000000000000000000
> > >
> > > Provisioning started
> > >
> > > Assign addresses for 4 elements
> > >
> > > Provisioning done:
> > >
> > > Mesh Node:
> > >
> > > UUID = F24B3F329DF200000000000000000000
> > >
> > > Primary = 00aa
> > >
> > > elements = 4
> > >
> > >
> > > [mesh-cfgclient]# menu config
> > >
> > > [mesh-cfgclient]# target 00aa
> > >
> > > [config: Target = 00aa] appkey-add 0001
> > >
> > > No response for "AppKeyAdd" from 00aa
> > >
> > >
> > > We have also confirmed that the local NetKey with index 0000 and
> > > appkey with index 0001 are both present, as used in above
> > > commands.
> > > As can be seen in config_db.json
> > > "netKeys":[
> > > {
> > > "index":"0000"
> > > }
> > > ],
> > > "appKeys":[
> > > {
> > > "boundNetKey":"0000",
> > > "index":"0001"
> > > }
> > > ],
> > >
> > >
> > > Please advise what can be done to resolve this issue.
> > >
> > >
> > > Thanks and regards
> > > Abhay Agarwal
> > > On Saturday, December 7, 2019, Stotland, Inga <
> > > inga.stotland@xxxxxxxxx
> > > > wrote:
> > > > Hi Abhay,
> > > >
> > > > On Fri, 2019-12-06 at 15:55 +0530, Abhay Agarwal wrote:
> > > > > Hi
> > > > >
> > > > > I am trying the mesh-cfgclient tool to control a sylvania
> > > > > smart+
> > > > > bulb with it.
> > > > > I am able to provision the device on PB-ADV.
> > > > >
> > > > > Unfortunately I am not able to configure the device. It shows
> > > > > the
> > > > > error message as
> > > > > [config: Target = 00aa]# appkey-add 0
> > > > > No response for "AppKeyAdd" from 00aa
> > > > >
> > > > > Note that I have been able to configure and control the
> > > > > device
> > > > > (on/off) using meshctl.
> > > > >
> > > > > Please advise what can be the issue and how to debug this.
> > > > >
> > > > > Thanks and Regards,
> > > > > Abhay Agarwal
> > > >
> > > > I suspect that the reason is for this behavior is the fact that
> > > > a
> > > > local AppKey with index "0" does not exist.
> > > >
> > > > Prior to sending AppKeys or NetKeys to a remote node,the keys
> > > > need
> > > > to be generated locally by executing
> > > > commands from the main mesh-cfgclient menu:
> > > > "create-subnet" for a NetKey
> > > > and
> > > > "create-appkey" for an AppKey
> > > >
> > > > Best regards,
> > > > Inga
> > > >
> > >
> > >
> >
> > Are you able to run the bluetoooth-meshd daemon in debug mode,
> > i.e.,
> > start it from the command line with "-nd" option? It would be
> > helpful
> > to see if the appkey message is being sent to the remote node.
> >
> > Best regardds,
> > Inga
> >
> >
> >
> >
> >
> >
> >
> > We have collected the logs from bluetooth-meshd daemon in debug
> > mode.
> > Unfortunately we are not able to identify the issue from the logs.
> > Corresponding logs are attached
> >
> >
> >
> > mesh/node.c:add_appkey_call() AddAppKey mesh/model.c:msg_send()
> > (6fff) 0x7ffe1ed067e0 mesh/model.c:msg_send() net_idx 0
> > mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 00
> > mesh/net.c:send_seg() segN 1 segment 0 seg_off 0
> > mesh/util.c:print_packet() 32648.191 Clr-Net Tx:
> > 007f00007b000100ae8001ec015adf1c432436804ca9c80fa700000000
> > mesh/util.c:print_packet() 32648.191 RX: Network [enc] ::
> > 22ea76ed1b921fab5aad2f88acf94d818b36972c22501d179da9617c2f
> > mesh/util.c:print_packet() 32648.191 RX: Network [clr] ::
> > 227f00007b000100ae8001ec015adf1c432436804ca9c80fa7 TX: Network 0001
> > -> 00ae :
> > 22ea76ed1b921fab5aad2f88acf94d818b36972c22501d179da9617c2f (29) :
> > TTL 127 : SEQ 00007b mesh/net.c:send_seg() segN 1 segment 1 seg_off
> > 12 mesh/util.c:print_packet() 32648.191 Clr-Net Tx:
> > 227f00007c000100ae8001ec21b594af6db74d46134340738200000000
> > mesh/util.c:print_packet() 32648.191 RX: Network [enc] ::
> > 22a61075641a39fd61601ad89e89e9464b1158b1cf21b126d875301654
> > mesh/util.c:print_packet() 32648.191 RX: Network [clr] ::
> > 227f00007c000100ae8001ec21b594af6db74d461343407382 TX: Network 0001
> > -> 00ae :
> > 22a61075641a39fd61601ad89e89e9464b1158b1cf21b126d875301654 (29) :
> > TTL 127 : SEQ 00007c ACK Rxed (7b) (to:1): 00000000 Resend Seg 0
> > net:0xd5ead0 dst:ae app_idx:000 mesh/net.c:send_seg() segN 1
> > segment 0 seg_off 0 ########### ------------- -------------
> > ########### mesh/net.c:send_seg() segN 1 segment 0 seg_off 0
> > mesh/util.c:print_packet() 32706.199 Clr-Net Tx:
> > 007f0000b5000100ae8001ec015adf1c432436804ca9c80fa700000000
> > mesh/util.c:print_packet() 32706.199 RX: Network [enc] ::
> > 22cbfc557d3a8a341dc7d97891419396648ddba961a57d45960c8ab796
> > mesh/util.c:print_packet() 32706.199 RX: Network [clr] ::
> > 227f0000b5000100ae8001ec015adf1c432436804ca9c80fa7 TX: Network 0001
> > -> 00ae :
> > 22cbfc557d3a8a341dc7d97891419396648ddba961a57d45960c8ab796 (29) :
> > TTL 127 : SEQ 0000b5 Resend Seg 1 net:0xd5ead0 dst:ae app_idx:000
> > mesh/net.c:send_seg() segN 1 segment 1 seg_off 12
> > mesh/util.c:print_packet() 32706.199 Clr-Net Tx:
> > 227f0000b6000100ae8001ec21b594af6db74d46134340738200000000
> > mesh/util.c:print_packet() 32706.200 RX: Network [enc] ::
> > 22d3f978cce5ab3b33a796e1341b6a742198e9144329357c536e4c1e0f
> > mesh/util.c:print_packet() 32706.200 RX: Network [clr] ::
> > 227f0000b6000100ae8001ec21b594af6db74d461343407382 TX: Network 0001
> > -> 00ae :
> > 22d3f978cce5ab3b33a796e1341b6a742198e9144329357c536e4c1e0f (29) :
> > TTL 127 : SEQ 0000b6 mesh/model.c:cmplt() Tx-->00ae (20 octets)
> > Failed (1) mesh/model.c:cmplt() Duration 60.000328 seconds
> > mesh/net.c:beacon_recv() KR: 1 -- IVU: 0 -- IV: 00000000
> >
> >
> > Please advise how to proceed to resolve this issue.
> >
> >
> >
> > Thanks and regards
> > Abhay Agarwal
> >
> >
> > It doesn't look like the remote node is responding at all.
> > Did you try simpler commands, e.g., "ttl-get"?
> >
> >
> > In fact, could you please try to issue "composition-get" right
> > after the node has been provisioned?
> >
> > Also, is the mesh daemon based on the latest code in the bluez
> > tree?
> > There's an issue that we juct discovered with the beaconing and it
> > may affect how the nodes communicate.
> > While it's being fixed, you may want to try to disable beaconing in
> > the daemon altogether:
> > In the node.c
> > @@ -503,9 +503,7 @@ static void update_net_settings
> > ....
> > - mode = node->beacon;
> > - if (mode == MESH_MODE_ENABLED || mode == MESH_MODE_DISABLED)
> > - mesh_net_set_beacon_mode(node->net, mode == MESH_MODE_ENABLED);
> > + mesh_net_set_beacon_mode(node->net, false);
> >
> >
> > You will have to recompile the daemon and re-provision the remote
> > node again.
> >
> > Thanks,
> > Inga
> >
>
>
> As suggested by you, I tried simpler commands like ttl-get. Also
> tried
> composition-get command just after provisioning, but none of the
> command seems to be working.
> I have also ensured that the mesh daemon is based on the latest code.
> The issue remains same even after disabling beaconing in daemon.
>
> To further debug the issue, I tried the mesh-cfgclient with a
> nrf52840
> PDK based mesh node (based on zephyr).
> Provisioning was successful and I collected logs on the node side
> (Attached below).
>
> Although no logs were detected on node with commands like ttl-get and
> composition-get. When using the command appkey-add, logs were
> detected
> on node and also I found the RX logs on mesh-daemon. Even though the
> issue remained same.
> Corresponding logs are attached
>
>
>
> [Bluetooth meshd logs for appkey-add]
>
> mesh/net.c:beacon_recv() KR: 0 -- IVU: 0 -- IV: 00000000
> mesh/node.c:add_appkey_call() AddAppKey
> mesh/model.c:msg_send() (6fff) 0x7ffcde4a7a90
> mesh/model.c:msg_send() net_idx 0
> mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 00
> mesh/net.c:send_seg() segN 1 segment 0 seg_off 0
> mesh/util.c:print_packet() 44418.387 Clr-Net Tx:
> 007f000004000100aa80001001e5a69e7158a452ecbff03e5200000000
> mesh/util.c:print_packet() 44418.387 RX: Network [enc] ::
> 0224f36a079c31c1e6af914b7153cdc129630c3bf7eb61bb4d14f1703d
> mesh/util.c:print_packet() 44418.387 RX: Network [clr] ::
> 027f000004000100aa80001001e5a69e7158a452ecbff03e52
> TX: Network 0001 -> 00aa :
> 0224f36a079c31c1e6af914b7153cdc129630c3bf7eb61bb4d14f1703d (29) : TTL
> 127 : SEQ 000004
> mesh/net.c:send_seg() segN 1 segment 1 seg_off 12
> mesh/util.c:print_packet() 44418.387 Clr-Net Tx:
> 027f000005000100aa80001021442c55f78e2a3717eece861100000000
> mesh/util.c:print_packet() 44418.387 RX: Network [enc] ::
> 025995af016c160f996d09acd63485a1a288ef283bceca18b3286abe3b
> mesh/util.c:print_packet() 44418.387 RX: Network [clr] ::
> 027f000005000100aa80001021442c55f78e2a3717eece8611
> TX: Network 0001 -> 00aa :
> 025995af016c160f996d09acd63485a1a288ef283bceca18b3286abe3b (29) : TTL
> 127 : SEQ 000005
> mesh/util.c:print_packet() 44419.371 RX: Network [enc] ::
> 02499b511b57d4201f8206e441af700321d7c65c83a62673
> mesh/util.c:print_packet() 44419.371 RX: Network [clr] ::
> 028700000000aa000100001000000002
> mesh/net.c:packet_received() check 000000aa
> mesh/net.c:msg_in_cache() Add 00aa + 000000 + 000000aa
> mesh/net.c:packet_received() RX: Network 00aa -> 0001 : TTL 0x07 : IV
> : 00000000 SEQ 0x000000
> RX: App 0x00aa -> 0x0001 : TTL 0x07 : SEQ 0x000000
> mesh/net.c:packet_received() CTL - 0004 RX
> ACK Rxed (4) (to:0): 00000002
> Resend Seg 0 net:0xe4c3a0 dst:aa app_idx:000
> mesh/net.c:send_seg() segN 1 segment 0 seg_off 0
>
>
>
> [Zephyr logs for provisioning]
>
> [00:00:00.190,000] <inf> bt_hci_core: Identity: 00:1a:7d:da:71:18
> (public)
> [00:00:00.190,000] <inf> bt_hci_core: HCI: version 4.0 (0x06)
> revision
> 0x22bb, manufacturer 0x000a
> [00:00:00.190,000] <inf> bt_hci_core: LMP: version 4.0 (0x06) subver
> 0x22bb
> [00:00:00.200,000] <dbg> bt_mesh_settings.mesh_commit: sub[0].net_idx
> 0xffff
> [00:00:00.200,000] <inf> bt_mesh_main: Device UUID:
> 00000000-0000-0000-0000-0000000~
> OOB Number: 2522
> [00:03:40.170,000] <wrn> bt_mesh_prov: Data for unknown transaction
> (2 != 0)
> [00:03:40.570,000] <wrn> bt_mesh_prov: Data for unknown transaction
> (2 != 0)
> [00:03:42.170,000] <wrn> bt_mesh_prov: Ignoring already received
> segment
> [00:03:42.570,000] <wrn> bt_mesh_prov: Got Start while there are
> unreceived segments
> [00:03:59.820,000] <wrn> bt_mesh_prov: Data for unknown transaction
> (5 != 0)
> [00:04:00.320,000] <wrn> bt_mesh_prov: Data for unknown transaction
> (5 != 0)
> [00:04:02.120,000] <wrn> bt_mesh_prov: Data for unknown transaction
> (5 != 0)
> [00:04:02.720,000] <wrn> bt_mesh_prov: Got Start while there are
> unreceived segments
> [00:04:02.920,000] <inf> bt_mesh_main: Primary Element: 0x00aa
> [00:04:02.920,000] <dbg> bt_mesh_main.bt_mesh_provision: net_idx
> 0x0000 flags 0x00 iv_index 0x0000
> [00:04:02.920,000] <dbg> bt_mesh_net.bt_mesh_net_create: idx 0 flags
> 0x00 iv_index 0
> [00:04:02.920,000] <dbg> bt_mesh_net.bt_mesh_net_create: NetKey
> f9780e1b1b7b6a63521c88381688032~
> [00:04:02.920,000] <dbg> bt_mesh_net.bt_mesh_net_keys_create: NID
> 0x02
> EncKey 9eb4e67c1aeb8d1c4c011f61b7b5d28~
> [00:04:02.920,000] <dbg> bt_mesh_net.bt_mesh_net_keys_create:
> PrivacyKey bc864c05a1add8379f01ba636ba19b5~
> [00:04:02.920,000] <dbg> bt_mesh_net.bt_mesh_net_keys_create: NetID
> f44f1061e97b1548
> [00:04:02.920,000] <dbg> bt_mesh_net.bt_mesh_net_keys_create:
> IdentityKey <log_strdup alloc failed>
> [00:04:02.920,000] <dbg> bt_mesh_net.bt_mesh_net_keys_create:
> BeaconKey <log_strdup alloc failed>
> [00:04:02.920,000] <dbg> bt_mesh_net.bt_mesh_net_beacon_update:
> NetIndex 0 Using current key
> [00:04:02.920,000] <dbg> bt_mesh_net.bt_mesh_net_beacon_update: flags
> 0x00, IVI 0x00000000
> [00:04:02.920,000] <dbg> bt_mesh_main.bt_mesh_provision: Storing
> network information persistently
> [00:04:02.920,000] <dbg> bt_mesh_settings.schedule_store: Waiting 0
> seconds
> [00:04:02.920,000] <dbg> bt_mesh_settings.bt_mesh_store_subnet:
> NetKeyIndex 0x000
> [00:04:02.930,000] <dbg> bt_mesh_settings.schedule_store: Waiting 0
> seconds
> [00:04:02.930,000] <dbg> bt_mesh_settings.schedule_store: Waiting 0
> seconds
> [00:04:02.930,000] <dbg> bt_mesh_settings.schedule_store: Waiting 0
> seconds
> [00:04:02.930,000] <dbg> bt_mesh_net.bt_mesh_net_beacon_update:
> NetIndex 0 Using current key
> [00:04:02.930,000] <dbg> bt_mesh_net.bt_mesh_net_beacon_update: flags
> 0x00, IVI 0x00000000
> [00:04:02.930,000] <dbg> bt_mesh_settings.store_pending:
> [00:04:02.930,000] <dbg> bt_mesh_settings.store_net_key: NetKeyIndex
> 0x000 NetKey <log_strdup alloc failed>
> [00:04:02.930,000] <dbg> bt_mesh_settings.store_net_key: Stored
> NetKey value
> [00:04:02.930,000] <dbg> bt_mesh_settings.store_pending_net: addr
> 0x00aa DevKey <log_strdup alloc failed>
> [00:04:02.930,000] <dbg> bt_mesh_settings.store_pending_net: Stored
> Network value
> [00:04:02.930,000] <dbg> bt_mesh_settings.store_pending_iv: Stored IV
> value
> [00:04:02.930,000] <dbg> bt_mesh_settings.store_pending_seq: Stored
> Seq value
>
>
>
> [Zephyr logs for appkey-add]
>
> [00:06:53.460,000] <dbg> bt_mesh_net.bt_mesh_net_recv: rssi -33
> net_if 0
> [00:06:53.460,000] <dbg> bt_mesh_net.bt_mesh_net_decode: 29 bytes:
> 025995af016c160f996d09acd63485a~
> [00:06:53.460,000] <dbg> bt_mesh_net.net_find_and_decrypt:
> [00:06:53.460,000] <dbg> bt_mesh_net.friend_decrypt: NID 0x02 net_idx
> 0x0000
> [00:06:53.460,000] <dbg> bt_mesh_net.net_decrypt: NID 0x02 net_idx
> 0x0000
> [00:06:53.460,000] <dbg> bt_mesh_net.net_decrypt: IVI 0 net->iv_index
> 0x00000000
> [00:06:53.460,000] <dbg> bt_mesh_net.net_decrypt: src 0x0001
> [00:06:53.460,000] <dbg> bt_mesh_net.bt_mesh_net_decode: Decryption
> successful. Payload len 25
> [00:06:53.460,000] <dbg> bt_mesh_net.bt_mesh_net_decode: src 0x0001
> dst 0x00aa ttl 127
> [00:06:53.460,000] <dbg> bt_mesh_net.bt_mesh_net_decode: PDU:
> 027f000005000100aa80001021442c5~
> [00:06:53.460,000] <dbg> bt_mesh_friend.bt_mesh_friend_match: No
> matching LPN for address 0x00aa
> [00:06:53.460,000] <dbg> bt_mesh_transport.bt_mesh_trans_recv: src
> 0x0001 dst 0x00aa seq 0x00000005 friend_match 0
> [00:06:53.460,000] <dbg> bt_mesh_transport.bt_mesh_trans_recv:
> Payload
> 80001021442c55f78e2a3717eece861~
> [00:06:53.460,000] <dbg> bt_mesh_transport.trans_seg: ASZMIC 0 AKF 0
> AID 0x00
> [00:06:53.460,000] <dbg> bt_mesh_transport.trans_seg: SeqZero 0x0004
> SegO 1 SegN 1
> [00:06:53.460,000] <dbg> bt_mesh_transport.seg_rx_alloc: New RX
> context. Block Complete 0x00000003
> [00:06:53.460,000] <dbg> bt_mesh_transport.trans_seg: Target len 1 *
> 12 + 12 = 24
> [00:06:53.460,000] <dbg> bt_mesh_transport.trans_seg: Received 1/1
> [00:06:54.170,000] <dbg> bt_mesh_transport.seg_ack: rx 0x002486a0
> [00:06:54.170,000] <dbg> bt_mesh_transport.send_ack: SeqZero 0x0004
> Block 0x00000002 OBO 0
> [00:06:54.170,000] <dbg> bt_mesh_transport.bt_mesh_ctl_send: src
> 0x00aa dst 0x0001 ttl 0xff ctl 0x00
> [00:06:54.170,000] <dbg> bt_mesh_transport.bt_mesh_ctl_send: len 6:
> 001000000002
> [00:06:54.170,000] <dbg> bt_mesh_friend.bt_mesh_friend_match: No
> matching LPN for address 0x0001
> [00:06:54.170,000] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x00aa dst
> 0x0001 len 7 headroom 9 tailroom 13
> [00:06:54.170,000] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 7:
> 00001000000002
> [00:06:54.170,000] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x000000
> [00:06:54.170,000] <dbg> bt_mesh_net.bt_mesh_net_encode: src 0x00aa
> dst 0x0001 ctl 1 seq 0x000000
> [00:06:54.780,000] <dbg> bt_mesh_transport.seg_ack: rx 0x002486a0
> [00:06:54.780,000] <dbg> bt_mesh_transport.send_ack: SeqZero 0x0004
> Block 0x00000002 OBO 0
> [00:06:54.780,000] <dbg> bt_mesh_transport.bt_mesh_ctl_send: src
> 0x00aa dst 0x0001 ttl 0xff ctl 0x00
> [00:06:54.780,000] <dbg> bt_mesh_transport.bt_mesh_ctl_send: len 6:
> 001000000002
> [00:06:54.780,000] <dbg> bt_mesh_friend.bt_mesh_friend_match: No
> matching LPN for address 0x0001
> [00:06:54.780,000] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x00aa dst
> 0x0001 len 7 headroom 9 tailroom 13
>
So, the logs indicate that both sides can hear each other and decode
the received packets at least on the network level.
If I had to make a guess, I'd say that for whatever reason the mesh
communication in your setup is *really* unreliable. I recall
encountering similar problems when using some laptop's internal BT
controller.
The fact that provisioning is successful, but the simple "ttl-get"
command is not getting through somewhat supports this theory. The
provisioning protocol is more robust: messages are retransmitted many
times until a response is recieved. "ttl-get" is a simple one mesh-
packet message that can be easily dropped. "AppKeyAdd", on the other
hand, is a segmented message, and therefore it's transmission is more
"persistent", relying on the acknowledgement of received messages (you
can see from the logs that at loeast some segments got through).
So, you can try the following things:
- Try a different BT controller (a BT dongle or a different machine) to
run the meshd daemon and mesh-cfgclient.
- Try playing with network transmit parameters on the meshd side. YOu
can do that by using mesh-cfgclient to configure the local node (the
one with 0001 unicast address):
>> target 0001
>> network-transmit-set 7 9
This will set network transmit count to 8 (max) and the interval to 100
ms. This will result in every message to be transmitted 8 times.
Then try to talk to the remote node again (target 00aa) and see if the
communication improves.
Best regards,
Inga
