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


Steve Brown
 

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


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



Steve Brown
 

Hi Trond,

The patch didn't fix the problem. I've attached the meshd and zephyr
debug output.

Steve

MESHD
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/node.c:dev_key_send_call() DevKeySend
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/model.c:mesh_model_send() mesh_model_send entered msg_len 0003
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/model.c:msg_send() msg_send entered: msg_len: 0003
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 00
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/net.c:send_seg() segN 0 segment 0 seg_off 0
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93738.961 Clr-Net Tx: 007f00000d000100aa00dd6f95b73a165c00000000
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93738.962 RX: Network [enc] :: 08ee4529cf4f9b4ad5f11b7e12d6e2b5f7aaaaab2c
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93738.962 RX: Network [clr] :: 087f00000d000100aa00dd6f95b73a165c
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93738.973 RX: Network [enc] :: 0870773c224755ec3a59147e44df996c33f1314f7ad4bb74a76f148166
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93738.973 RX: Network [clr] :: 080700001000aa0001808040048d32264e904a86e51d1faca4
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/net.c:msg_in_cache() Add 00aa + 000010 + 904a86e5
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: RX: Network 00aa -> 0001 : TTL 0x07 : IV : 00000000 SEQ 0x000010 : RSSI -64
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: RX: App 0x00aa -> 0x0001 : TTL 0x07 : SEQ 0x000010 : RSSI -64
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/net.c:seg_rxed() RXed (new: 0010 000010 size: 12 len: 60) 0 of 4
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/net.c:seg_rxed() Queue Size: 0
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/net.c:seg_rxed() First Seg 0000
Nov 3 03:55:38 mesh0 bluetooth-meshd[21346]: mesh/net.c:seg_rxed() NAK: 1 expected:0000001f largest:0000001f flags:00000001
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93739.094 RX: Network [enc] :: 08464c2b449dfb949f95719d40db06f716b3d59153c0065fe0e7c38c24
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93739.094 RX: Network [clr] :: 080700001100aa000180804024db714c0a58f47c3969824188
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/net.c:msg_in_cache() Add 00aa + 000011 + 58f47c39
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: RX: Network 00aa -> 0001 : TTL 0x07 : IV : 00000000 SEQ 0x000011 : RSSI -63
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: RX: App 0x00aa -> 0x0001 : TTL 0x07 : SEQ 0x000011 : RSSI -63
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/net.c:seg_rxed() RXed (old: 0010 000011 size:12) 1 of 4
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/net.c:seg_rxed() NAK: 1 expected:0000001f largest:0000001e flags:00000003
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93739.216 RX: Network [enc] :: 0863652c2d41a065270a3080632b7e6dd8578d3007f9f4886bedac4d60
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93739.216 RX: Network [clr] :: 080700001200aa000180804044ae8709c296e7ef543a2dc728
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/net.c:msg_in_cache() Add 00aa + 000012 + 96e7ef54
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: RX: Network 00aa -> 0001 : TTL 0x07 : IV : 00000000 SEQ 0x000012 : RSSI -64
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: RX: App 0x00aa -> 0x0001 : TTL 0x07 : SEQ 0x000012 : RSSI -64
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/net.c:seg_rxed() RXed (old: 0010 000012 size:12) 2 of 4
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/net.c:seg_rxed() NAK: 1 expected:0000001f largest:0000001c flags:00000007
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93739.337 RX: Network [enc] :: 08dccaf88a308e5c13fed895ba3ff56430b7beb8016329cc2e39f02853
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93739.337 RX: Network [clr] :: 080700001300aa000180804064f8f2e2ca3c5dfd10f57a2e5e
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/net.c:msg_in_cache() Add 00aa + 000013 + 3c5dfd10
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: RX: Network 00aa -> 0001 : TTL 0x07 : IV : 00000000 SEQ 0x000013 : RSSI -64
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: RX: App 0x00aa -> 0x0001 : TTL 0x07 : SEQ 0x000013 : RSSI -64
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/net.c:seg_rxed() RXed (old: 0010 000013 size:12) 3 of 4
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/net.c:seg_rxed() NAK: 1 expected:0000001f largest:00000018 flags:0000000f
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93739.486 RX: Network [enc] :: 08a4cc8cb59cb690e547277c1e15aff2263b0f62a7ae9c
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93739.486 RX: Network [clr] :: 080700001400aa000180804084b53f74e0973a
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/net.c:msg_in_cache() Add 00aa + 000014 + 4084b53f
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: RX: Network 00aa -> 0001 : TTL 0x07 : IV : 00000000 SEQ 0x000014 : RSSI -64
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: RX: App 0x00aa -> 0x0001 : TTL 0x07 : SEQ 0x000014 : RSSI -64
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/net.c:seg_rxed() RXed (old: 0010 000014 size:6) 4 of 4
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/net.c:send_net_ack() Send ACK to Segs: 0000001f
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 00
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: model.c - Failed to decrypt application payload
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93739.488 RX: Network [enc] :: 08b0b85593f65359b8700da848ae7429129b05bbbb3f48fe
Nov 3 03:55:39 mesh0 bluetooth-meshd[21346]: mesh/util.c:print_packet() 93739.488 RX: Network [clr] :: 08ff000010000100aa0000400000001f

zephyr
[14:52:52.859,710] <dbg> bt_mesh_cfg_srv.dev_comp_data_get: net_idx 0x0000 app_idx 0xfffe src 0x0001 len 1: 00
[14:52:52.859,741] <dbg> bt_mesh_access.model_send: net_idx 0x0000 app_idx 0xfffe dst 0x0001
[14:52:52.859,771] <dbg> bt_mesh_access.model_send: len 50: 0200f105000000000a0003000000050~
[14:52:52.859,771] <dbg> bt_mesh_transport.bt_mesh_trans_send: net_idx 0x0000 app_idx 0xfffe dst 0x0001
[14:52:52.859,802] <dbg> bt_mesh_transport.bt_mesh_trans_send: len 50: 0200f105000000000a0003000000050~
[14:52:52.859,954] <dbg> bt_mesh_transport.send_seg: src 0x00aa dst 0x0001 app_idx 0xfffe aszmic 1 sdu_len 54
[14:52:52.859,985] <dbg> bt_mesh_transport.send_seg: SeqZero 0x000b (segs: 5)
[14:52:52.859,985] <dbg> bt_mesh_transport.send_seg: seg 0: 86044bbdb2d803234191a592
[14:52:52.860,015] <dbg> bt_mesh_transport.send_seg: seg 1: 1271612ba4accf550958b3df
[14:52:52.860,015] <dbg> bt_mesh_transport.send_seg: seg 2: 43943905c3f425318a493eec
[14:52:52.860,046] <dbg> bt_mesh_transport.send_seg: seg 3: ad581efacf03a6d519833d03
[14:52:52.860,076] <dbg> bt_mesh_transport.send_seg: seg 4: 9f6585f87caa
[14:52:52.860,076] <dbg> bt_mesh_transport.seg_tx_send_unacked: SeqZero: 0x000b Attempts: 4
[14:52:52.860,107] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 0/4
[14:52:52.860,107] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x00aa dst 0x0001 len 16 headroom 9 tailroom 4
[14:52:52.860,107] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 16: 80802c0486044bbdb2d803234191a59~
[14:52:52.860,137] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x00000b
[14:52:52.860,137] <dbg> bt_mesh_net.net_header_encode: src 0x00aa dst 0x0001 ctl 0 seq 0x00000b
[14:52:52.860,290] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 1/4
[14:52:52.860,321] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x00aa dst 0x0001 len 16 headroom 9 tailroom 4
[14:52:52.860,321] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 16: 80802c241271612ba4accf550958b3d~
[14:52:52.860,321] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x00000c
[14:52:52.860,351] <dbg> bt_mesh_net.net_header_encode: src 0x00aa dst 0x0001 ctl 0 seq 0x00000c
[14:52:52.860,565] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 2/4
[14:52:52.860,595] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x00aa dst 0x0001 len 16 headroom 9 tailroom 4
[14:52:52.860,595] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 16: 80802c4443943905c3f425318a493ee~
[14:52:52.860,595] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x00000d
[14:52:52.860,626] <dbg> bt_mesh_net.net_header_encode: src 0x00aa dst 0x0001 ctl 0 seq 0x00000d
[14:52:52.860,778] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 3/4
[14:52:52.860,778] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x00aa dst 0x0001 len 16 headroom 9 tailroom 4
[14:52:52.860,809] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 16: 80802c64ad581efacf03a6d519833d0~
[14:52:52.860,809] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x00000e
[14:52:52.860,809] <dbg> bt_mesh_net.net_header_encode: src 0x00aa dst 0x0001 ctl 0 seq 0x00000e
[14:52:52.860,961] <dbg> bt_mesh_transport.seg_tx_send_unacked: Sending 4/4
[14:52:52.860,992] <dbg> bt_mesh_net.bt_mesh_net_send: src 0x00aa dst 0x0001 len 10 headroom 9 tailroom 10
[14:52:52.860,992] <dbg> bt_mesh_net.bt_mesh_net_send: Payload len 10: <log_strdup alloc failed>
[14:52:52.860,992] <dbg> bt_mesh_net.bt_mesh_net_send: Seq 0x00000f
[14:52:52.861,022] <dbg> bt_mesh_net.net_header_encode: src 0x00aa dst 0x0001 ctl 0 seq 0x00000f
[14:52:52.861,114] <dbg> bt_mesh_access.bt_mesh_model_recv: No OpCode 0x00008008 for elem 1
[14:52:52.861,145] <dbg> bt_mesh_access.bt_mesh_model_recv: No OpCode 0x00008008 for elem 2
[14:52:52.861,145] <dbg> bt_mesh_access.bt_mesh_model_recv: No OpCode 0x00008008 for elem 3
[14:52:53.358,947] <dbg> bt_mesh_net.bt_mesh_net_recv: rssi -51 net_if 0

On Tue, 2020-11-03 at 08:21 +0000, Snekvik, Trond wrote:
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@ewol.com>
Sent: Monday, November 2, 2020 18:13
To: zephyr-devel@lists.zephyrproject.org <
zephyr-devel@lists.zephyrproject.org>
Cc: Snekvik, Trond <Trond.Einar.Snekvik@nordicsemi.no>
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


SUCCESS


Steve Brown
 

Hi Trond,

On further testing, it now works.

I must have not properly flashed my board.

Sorry for the noise and thanks for the fix.

Steve

On Tue, 2020-11-03 at 08:21 +0000, Snekvik, Trond wrote:
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@ewol.com>
Sent: Monday, November 2, 2020 18:13
To: zephyr-devel@lists.zephyrproject.org <
zephyr-devel@lists.zephyrproject.org>
Cc: Snekvik, Trond <Trond.Einar.Snekvik@nordicsemi.no>
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


Trond Snekvik
 

That's good to hear, thanks for confirming.

Trond


From: Steve Brown <sbrown@...>
Sent: Tuesday, November 3, 2020 10:59
To: Snekvik, Trond <Trond.Einar.Snekvik@...>; zephyr-devel@... <zephyr-devel@...>
Subject: Re: Bluez' mesh-cfgclient fails to retrieve composition data from onoff-app sample
 
Hi Trond,

On further testing, it now works.

I must have not properly flashed my board.

Sorry for the noise and thanks for the fix.

Steve

On Tue, 2020-11-03 at 08:21 +0000, Snekvik, Trond wrote:
> 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://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fzephyrproject-rtos%2Fzephyr%2Fpull%2F29739&amp;data=04%7C01%7CTrond.Einar.Snekvik%40nordicsemi.no%7C3e56da8edf5a40e8722908d87fdf281a%7C28e5afa2bf6f419a8cf6b31c6e9e5e8d%7C0%7C0%7C637399944054389517%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000&amp;sdata=9AyTQRjqqyA50x6ElnFbQN1gyOj8c1a5fxGXV4%2FOEOM%3D&amp;reserved=0
>
> 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
>
>