Re: Bluez' mesh-cfgclient fails to retrieve composition data from onoff-app sample


Trond Snekvik
 

Hi, 

Looks like this is caused by a discrepancy between what MIC length was passed into the encryption function and packet assembly when the MIC length is 8 (which just happens in segmented messages).


Please test it and provide feedback if you can.

Thanks for the detailed bug report!

Trond


From: Steve Brown <sbrown@...>
Sent: Monday, November 2, 2020 18:13
To: zephyr-devel@... <zephyr-devel@...>
Cc: Snekvik, Trond <Trond.Einar.Snekvik@...>
Subject: Bluez' mesh-cfgclient fails to retrieve composition data from onoff-app sample
 
I bisected this to eca014115 
Bluetooth: Mesh: Isolate cryptographic material

I suspect segmented messages. The successful sequence number starts at
2 whereas the failing one starts at 1.

I'm not familiar enough with the code to go further than this.

Nothing appears in the meshd debug log with the failing case.

Provisioning succeeds and configuration commands that return
unsegmented messages, like ttl-get, work.

Steve

FAILING TRACE
[00:00:44.745,727] <dbg> bt_mesh_access.model_send: net_idx 0x0000 app_idx 0xfffe dst 0x0001
[00:00:44.745,758] <dbg> bt_mesh_access.model_send: len 50: 0200f105000000000a0003000000050~
[00:00:44.745,788] <dbg> bt_mesh_transport.bt_mesh_trans_send: net_idx 0x0000 app_idx 0xfffe dst 0x0001
[00:00:44.745,819] <dbg> bt_mesh_transport.bt_mesh_trans_send: len 50: 0200f105000000000a0003000000050~
[00:00:44.745,971] <dbg> bt_mesh_transport.send_seg: src 0x0116 dst 0x0001 app_idx 0xfffe aszmic 1 sdu_len 54
[00:00:44.745,971] <dbg> bt_mesh_transport.send_seg: SeqZero 0x0001 (segs: 5)
[00:00:44.746,002] <dbg> bt_mesh_transport.send_seg: seg 0: 581b6de7e895153634729e5a
[00:00:44.746,032] <dbg> bt_mesh_transport.send_seg: seg 1: 78298189c7f317ef0d1bf4c0
[00:00:44.746,032] <dbg> bt_mesh_transport.send_seg: seg 2: 3def2b3f3ff14af374b4cda1
[00:00:44.746,063] <dbg> bt_mesh_transport.send_seg: seg 3: ce9fa72cb97cf05f4986433d
[00:00:44.746,063] <dbg> bt_mesh_transport.send_seg: seg 4: b4e6c4dc7c54
[00:00:44.746,093] <dbg> bt_mesh_transport.seg_tx_send_unacked: SeqZero: 0x0001 Attempts: 4
[00:00:44.746,093] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 0/4
[00:00:44.746,124] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x0116 dst 0x0001 len 16 headroom 9 tailroom 4
[00:00:44.746,124] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 16: 80800404581b6de7e895153634729e5~
[00:00:44.746,124] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x000001
[00:00:44.746,154] <dbg> bt_mesh_net.net_header_encode: src 0x0116 dst 0x0001 ctl 0 seq 0x000001
[00:00:44.746,307] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 1/4
[00:00:44.746,307] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x0116 dst 0x0001 len 16 headroom 9 tailroom 4
[00:00:44.746,337] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 16: 8080042478298189c7f317ef0d1bf4c~
[00:00:44.746,337] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x000002
[00:00:44.746,337] <dbg> bt_mesh_net.net_header_encode: src 0x0116 dst 0x0001 ctl 0 seq 0x000002
[00:00:44.746,490] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 2/4
[00:00:44.746,520] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x0116 dst 0x0001 len 16 headroom 9 tailroom 4
[00:00:44.746,520] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 16: 808004443def2b3f3ff14af374b4cda~
[00:00:44.746,551] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x000003
[00:00:44.746,551] <dbg> bt_mesh_net.net_header_encode: src 0x0116 dst 0x0001 ctl 0 seq 0x000003
[00:00:44.746,704] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 3/4
[00:00:44.746,704] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x0116 dst 0x0001 len 16 headroom 9 tailroom 4
[00:00:44.746,734] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 16: 80800464ce9fa72cb97cf05f4986433~
[00:00:44.746,734] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x000004
[00:00:44.746,765] <dbg> bt_mesh_net.net_header_encode: src 0x0116 dst 0x0001 ctl 0 seq 0x000004
[00:00:44.746,917] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 4/4
[00:00:44.746,917] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x0116 dst 0x0001 len 10 headroom 9 tailroom 10
[00:00:44.746,917] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 10: <log_strdup alloc failed>
[00:00:44.746,917] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x000005
[00:00:44.746,948] <dbg> bt_mesh_net.net_header_encode: src 0x0116 dst 0x0001 ctl 0 seq 0x000005

SUCCESS
[00:00:50.364,929] <dbg> bt_mesh_cfg_srv.dev_comp_data_get: net_idx 0x0000 app_idx 0xfffe src 0x0001 len 1: 00
[00:00:50.364,959] <dbg> bt_mesh_access.model_send: net_idx 0x0000 app_idx 0xfffe dst 0x0001
[00:00:50.364,990] <dbg> bt_mesh_access.model_send: len 50: 0200f105000000000a0003000000050~
[00:00:50.364,990] <dbg> bt_mesh_transport.bt_mesh_trans_send: net_idx 0x0000 app_idx 0xfffe dst 0x0001
[00:00:50.365,051] <dbg> bt_mesh_transport.bt_mesh_trans_send: len 50: 0200f105000000000a0003000000050~
[00:00:50.365,203] <dbg> bt_mesh_transport.send_seg: src 0x011a dst 0x0001 app_idx 0xfffe aszmic 1 sdu_len 58
[00:00:50.365,203] <dbg> bt_mesh_transport.send_seg: SeqZero 0x0002 (segs: 5)
[00:00:50.365,234] <dbg> bt_mesh_transport.send_seg: seg 0: 0c0139ab229a128ab4d9da66
[00:00:50.365,264] <dbg> bt_mesh_transport.send_seg: seg 1: 7911abbd986ab5cc2ba3a7fd
[00:00:50.365,264] <dbg> bt_mesh_transport.send_seg: seg 2: b9460beeec1aca3c73012043
[00:00:50.365,295] <dbg> bt_mesh_transport.send_seg: seg 3: 254d22b179271b62687efbed
[00:00:50.365,325] <dbg> bt_mesh_transport.send_seg: seg 4: 6c7b29d675eb290476cd
[00:00:50.365,325] <dbg> bt_mesh_transport.seg_tx_send_unacked: SeqZero: 0x0002 Attempts: 4
[00:00:50.365,325] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 0/4
[00:00:50.365,356] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x011a dst 0x0001 len 16 headroom 9 tailroom 4
[00:00:50.365,356] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 16: 808008040c0139ab229a128ab4d9da6~
[00:00:50.365,386] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x000002
[00:00:50.365,386] <dbg> bt_mesh_net.net_header_encode: src 0x011a dst 0x0001 ctl 0 seq 0x000002
[00:00:50.365,539] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 1/4
[00:00:50.365,539] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x011a dst 0x0001 len 16 headroom 9 tailroom 4
[00:00:50.365,570] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 16: 808008247911abbd986ab5cc2ba3a7f~
[00:00:50.365,570] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x000003
[00:00:50.365,600] <dbg> bt_mesh_net.net_header_encode: src 0x011a dst 0x0001 ctl 0 seq 0x000003
[00:00:50.365,722] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 2/4
[00:00:50.365,753] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x011a dst 0x0001 len 16 headroom 9 tailroom 4
[00:00:50.365,783] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 16: 80800844b9460beeec1aca3c7301204~
[00:00:50.365,783] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x000004
[00:00:50.365,783] <dbg> bt_mesh_net.net_header_encode: src 0x011a dst 0x0001 ctl 0 seq 0x000004
[00:00:50.365,936] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 3/4
[00:00:50.365,936] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x011a dst 0x0001 len 16 headroom 9 tailroom 4
[00:00:50.365,966] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 16: <log_strdup alloc failed>
[00:00:50.365,966] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x000005
[00:00:50.365,966] <dbg> bt_mesh_net.net_header_encode: src 0x011a dst 0x0001 ctl 0 seq 0x000005
[00:00:50.366,119] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 4/4
[00:00:50.366,149] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x011a dst 0x0001 len 14 headroom 9 tailroom 6
[00:00:50.366,149] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 14: <log_strdup alloc failed>
[00:00:50.366,149] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x000006
[00:00:50.366,149] <dbg> bt_mesh_net.net_header_encode: src 0x011a dst 0x0001 ctl 0 seq 0x000006


Join devel@lists.zephyrproject.org to automatically receive all group messages.