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).

I have made PR:
https://github.com/zephyrproject-rtos/zephyr/pull/29739

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