Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bluetooth Mesh friendship is cleared due to no Friend response reception #22088

Closed
DHortelano opened this issue Jan 22, 2020 · 7 comments · Fixed by #22313
Closed

Bluetooth Mesh friendship is cleared due to no Friend response reception #22088

DHortelano opened this issue Jan 22, 2020 · 7 comments · Fixed by #22313
Assignees
Labels
area: Bluetooth Mesh area: Bluetooth bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug

Comments

@DHortelano
Copy link

Describe the bug
In the friendship established between a Friend Node (FN) and a Low Power Node (LPN) in a Bluetooth Mesh, the LPN generates and sends the Friend Poll message, which is correctly received by the FN. However, after that, the LPN is not able to start the scanning, with the following debug output:
[00:00:32.176,910] bt_mesh_adv: starting scan failed (err -5)
This produces the FN response is not received, and after some retries the friendship is cleared.

To Reproduce
Steps to reproduce the behavior:

  1. Establish a Friendiship between a LPN and a FN, using default configuration
  2. After the Friend Poll, the LPN is not able to scan
  3. Output shows bt_mesh_adv: starting scan failed (err -5)
  4. After the timeout expires, the friendship is cleared

Expected behavior
The LPN receives the Friend response

Screenshots or console output
Debugging output from LPN using CONFIG_BT_MESH_DEBUG_LOW_POWER and CONFIG_BT_MESH_DEBUG_ADV options:

Initializing...                                                                                                                                  
Unicast address: 0x0003                                                                                                                          
Bluetooth initialized                                                                                                                            
Mesh initialized                                                                                                                                 
Loading stored settings                                                                                                                          
Provisioning completed                                                                                                                           
Configuring...                                                                                                                                   
Publishing heartbeat messages                                                                                                                    
Configuration complete                                                                                                                           
[00:00:00.011,169] <inf> fs_nvs: 8 Sectors of 4096 bytes                                                                                         
[00:00:00.011,169] <inf> fs_nvs: alloc wra: 0, ff0                                                                                               
[00:00:00.011,169] <inf> fs_nvs: data wra: 0, 0                                                                                                  
[00:00:00.012,512] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)                                                                 
[00:00:00.012,542] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)                                                                                
--- 9 messages dropped ---                                                                                                                       
[00:00:00.024,627] <dbg> bt_mesh_lpn.bt_mesh_lpn_init:                                                                                           
[00:00:00.024,627] <dbg> bt_mesh_adv.bt_mesh_scan_enable:                                                                                        
[00:00:00.024,902] <dbg> bt_mesh_lpn.bt_mesh_lpn_init: Waiting 1000 ms for messages                                                              
[00:00:00.024,902] <dbg> bt_mesh_lpn.lpn_set_state: disabled -> timer                                                                            
[00:00:00.067,260] <dbg> bt_mesh_lpn.bt_mesh_lpn_msg_received: Restarting establishment timer                                                    
[00:00:00.069,091] <dbg> bt_mesh_lpn.bt_mesh_lpn_msg_received: Restarting establishment timer                                                    
[00:00:00.069,549] <dbg> bt_mesh_lpn.bt_mesh_lpn_msg_received: Restarting establishment timer                                                    
[00:00:00.069,976] <dbg> bt_mesh_lpn.bt_mesh_lpn_msg_received: Restarting establishment timer                                                    
[00:00:00.070,190] <dbg> bt_mesh_lpn.bt_mesh_lpn_group_add: group 0xc000                                                                         
[00:00:00.070,434] <dbg> bt_mesh_lpn.bt_mesh_lpn_msg_received: Restarting establishment timer                                                    
[00:00:00.070,892] <dbg> bt_mesh_lpn.bt_mesh_lpn_msg_received: Restarting establishment timer                                                    
[00:00:00.071,044] <dbg> bt_mesh_lpn.bt_mesh_lpn_msg_received: Restarting establishment timer                                                    
[00:00:00.071,289] <wrn> bt_mesh_cfg_cli: Unexpected App Key Status message                                                                      
[00:00:00.071,289] <dbg> bt_mesh_lpn.bt_mesh_lpn_msg_received: Restarting establishment timer                                                    
[00:00:00.071,533] <wrn> bt_mesh_cfg_cli: Unexpected Model App Status message                                                                    
[00:00:00.071,533] <dbg> bt_mesh_lpn.bt_mesh_lpn_msg_received: Restarting establishment timer                                                    
[00:00:00.071,746] <wrn> bt_mesh_cfg_cli: Unexpected Model App Status message                                                                    
[00:00:00.071,777] <dbg> bt_mesh_lpn.bt_mesh_lpn_msg_received: Restarting establishment timer                                                    
[00:00:00.072,021] <wrn> bt_mesh_cfg_cli: Unexpected Model Subscription Status message                                                           
[00:00:00.072,021] <dbg> bt_mesh_lpn.bt_mesh_lpn_msg_received: Restarting establishment timer                                                    
[00:00:00.072,265] <wrn> bt_mesh_cfg_cli: Unexpected Heartbeat Publication Status message                                                        
[00:00:00.072,296] <dbg> bt_mesh_lpn.bt_mesh_lpn_msg_received: Restarting establishment timer                                                    
[00:00:00.072,601] <wrn> bt_mesh_transport: Ignoring heartbeat to non-subscribed destination                                                     
[00:00:00.072,631] <dbg> bt_mesh_lpn.bt_mesh_lpn_msg_received: Restarting establishment timer                                                    
[00:00:00.072,784] <dbg> bt_mesh_adv.bt_mesh_adv_send: type 0x01 len 21: 373fa347ad8cf0510fa9e4e308e7016~                                        
[00:00:00.072,875] <dbg> bt_mesh_adv.adv_send: type 1 len 21: 373fa347ad8cf0510fa9e4e308e7016~                                                   
[00:00:00.072,875] <dbg> bt_mesh_adv.adv_send: count 3 interval 20ms duration 120ms                                                              
[00:00:00.073,577] <dbg> bt_mesh_adv.adv_send: Advertising started. Sleeping 120 ms                                                              
[00:00:00.193,786] <dbg> bt_mesh_adv.adv_send: Advertising stopped                                                                               
[00:00:01.072,692] <dbg> bt_mesh_lpn.lpn_timeout: state: timer                                                                                   
[00:00:01.072,692] <dbg> bt_mesh_lpn.lpn_timeout: Starting to look for Friend nodes                                                              
[00:00:01.072,723] <dbg> bt_mesh_lpn.lpn_set_state: timer -> enabled                                                                             
[00:00:01.072,723] <dbg> bt_mesh_lpn.send_friend_req:                                                                                            
[00:00:01.072,875] <dbg> bt_mesh_adv.bt_mesh_adv_send: type 0x01 len 28: 37d544ee68f31aa29525ffd3c210726~                                        
[00:00:01.072,937] <dbg> bt_mesh_adv.adv_send: type 1 len 28: 37d544ee68f31aa29525ffd3c210726~                                                   
[00:00:01.072,937] <dbg> bt_mesh_adv.adv_send: count 2 interval 20ms duration 90ms                                                               
[00:00:01.073,577] <dbg> bt_mesh_lpn.lpn_set_state: enabled -> wait offer                                                                        
[00:00:01.073,577] <dbg> bt_mesh_adv.adv_send: Advertising started. Sleeping 90 ms                                                               
[00:00:01.163,848] <dbg> bt_mesh_adv.adv_send: Advertising stopped                                                                               
[00:00:01.719,512] <dbg> bt_mesh_lpn.bt_mesh_lpn_friend_offer: recv_win 255 queue_size 16 sub_list_size 3 rssi -40 counter 0                     
--- 1 messages dropped ---                                                                                                                       
[00:00:01.721,984] <dbg> bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00                                                                        
[00:00:01.722,106] <dbg> bt_mesh_adv.bt_mesh_adv_send: type 0x01 len 19: 6826064ea4a0815b994af614d212464~                                        
[00:00:01.722,198] <dbg> bt_mesh_adv.adv_send: type 1 len 19: 6826064ea4a0815b994af614d212464~                                                   
[00:00:01.722,198] <dbg> bt_mesh_adv.adv_send: count 2 interval 20ms duration 90ms                                                               
[00:00:01.722,839] <dbg> bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait offer                                                       
[00:00:01.722,839] <dbg> bt_mesh_adv.adv_send: Advertising started. Sleeping 90 ms                                                               
[00:00:01.813,110] <dbg> bt_mesh_adv.adv_send: Advertising stopped                                                                               
[00:00:01.932,800] <dbg> bt_mesh_adv.bt_mesh_scan_cb: len 26: 192a6871a75b3159d1d16e55efcdb79~                                                   
[00:00:01.932,922] <inf> bt_mesh_lpn: Friendship established with 0x0001                                                                         
[00:00:01.932,922] <dbg> bt_mesh_lpn.friend_response_received: lpn->sent_req 0x01                                                                           
[00:00:01.932,952] <dbg> bt_mesh_adv.bt_mesh_scan_disable:                                                                                       
[00:00:01.933,197] <dbg> bt_mesh_lpn.lpn_set_state: wait offer -> established                                                                    
[00:00:01.933,197] <dbg> bt_mesh_lpn.bt_mesh_lpn_friend_update: flags 0x00 iv_index 0x00000000 md 0                                              
[00:00:01.933,197] <dbg> bt_mesh_lpn.sub_update: op 0x07 sent_req 0x00                                                                           
[00:00:01.933,349] <dbg> bt_mesh_adv.bt_mesh_adv_send: type 0x01 len 21: <log_strdup alloc failed>                                               
[00:00:01.933,380] <dbg> bt_mesh_lpn.sub_update: op 0x08 sent_req 0x07                                                                           
[00:00:01.933,410] <dbg> bt_mesh_adv.adv_send: type 1 len 21: <log_strdup alloc failed>                                                          
[00:00:01.933,441] <dbg> bt_mesh_adv.adv_send: count 2 interval 20ms duration 90ms                                                               
[00:00:01.933,959] <dbg> bt_mesh_lpn.req_sent: req 0x07 duration 90 err 0 state established                                                      
[00:00:01.933,959] <dbg> bt_mesh_lpn.lpn_set_state: established -> recv delay                                                                    
[00:00:01.933,990] <dbg> bt_mesh_adv.adv_send: Advertising started. Sleeping 90 ms                                                               
[00:00:02.024,078] <dbg> bt_mesh_lpn.lpn_timeout: state: recv delay                                                                              
[00:00:02.024,078] <dbg> bt_mesh_adv.bt_mesh_scan_enable:                                                                                        
[00:00:02.024,353] <dbg> bt_mesh_adv.adv_send: Advertising stopped                                                                               
[00:00:02.029,998] <err> bt_mesh_adv: starting scan failed (err -5)                                                                              
[00:00:02.029,998] <dbg> bt_mesh_lpn.lpn_set_state: recv delay -> wait update                                                                    
[00:00:02.379,150] <dbg> bt_mesh_lpn.lpn_timeout: state: wait update                                                                             
[00:00:02.379,180] <wrn> bt_mesh_lpn: No response from Friend during ReceiveWindow                                                               
[00:00:02.379,180] <dbg> bt_mesh_adv.bt_mesh_scan_disable:                                                                                       
[00:00:02.379,180] <dbg> bt_mesh_lpn.lpn_set_state: wait update -> established                                                                   
[00:00:02.479,248] <dbg> bt_mesh_lpn.lpn_timeout: state: established                                                                             
[00:00:02.479,248] <dbg> bt_mesh_lpn.sub_update: op 0x07 sent_req 0x00                                                                           
[00:00:02.479,400] <dbg> bt_mesh_adv.bt_mesh_adv_send: type 0x01 len 21: 68a123aa2fa3d96a54e52c0673a7248~                                        
[00:00:02.479,461] <dbg> bt_mesh_adv.adv_send: type 1 len 21: 68a123aa2fa3d96a54e52c0673a7248~                                                   
[00:00:02.479,461] <dbg> bt_mesh_adv.adv_send: count 2 interval 20ms duration 90ms                                                               
[00:00:02.480,010] <dbg> bt_mesh_lpn.req_sent: req 0x07 duration 90 err 0 state established                                                      
[00:00:02.480,041] <dbg> bt_mesh_lpn.lpn_set_state: established -> recv delay                                                                    
[00:00:02.480,041] <dbg> bt_mesh_adv.adv_send: Advertising started. Sleeping 90 ms                                                                                                       
[00:00:02.570,129] <dbg> bt_mesh_lpn.lpn_timeout: state: recv delay                                                                              
[00:00:02.570,129] <dbg> bt_mesh_adv.bt_mesh_scan_enable:                                                                                        
[00:00:02.570,404] <dbg> bt_mesh_adv.adv_send: Advertising stopped                                                                               
[00:00:02.576,049] <err> bt_mesh_adv: starting scan failed (err -5)                                                                              
[00:00:02.576,049] <dbg> bt_mesh_lpn.lpn_set_state: recv delay -> wait update                                                                    
[00:00:02.925,201] <dbg> bt_mesh_lpn.lpn_timeout: state: wait update                                                                             
[00:00:02.925,231] <wrn> bt_mesh_lpn: No response from Friend during ReceiveWindow                                                               
[00:00:02.925,231] <dbg> bt_mesh_adv.bt_mesh_scan_disable:                                                                                       
[00:00:02.925,231] <dbg> bt_mesh_lpn.lpn_set_state: wait update -> established                                                                   
[00:00:03.025,299] <dbg> bt_mesh_lpn.lpn_timeout: state: established                                                                             
[00:00:03.025,299] <dbg> bt_mesh_lpn.sub_update: op 0x07 sent_req 0x00                                                                           
[00:00:03.025,451] <dbg> bt_mesh_adv.bt_mesh_adv_send: type 0x01 len 21: 684b5758589ece2ea58eb80e6762f84~                                        
[00:00:03.025,512] <dbg> bt_mesh_adv.adv_send: type 1 len 21: 684b5758589ece2ea58eb80e6762f84~                                                   
[00:00:03.025,512] <dbg> bt_mesh_adv.adv_send: count 2 interval 20ms duration 90ms                                                               
[00:00:03.026,062] <dbg> bt_mesh_lpn.req_sent: req 0x07 duration 90 err 0 state established                                                      
[00:00:03.026,062] <dbg> bt_mesh_lpn.lpn_set_state: established -> recv delay                                                                    
[00:00:03.026,092] <dbg> bt_mesh_adv.adv_send: Advertising started. Sleeping 90 ms                                                                                                       
[00:00:03.116,180] <dbg> bt_mesh_lpn.lpn_timeout: state: recv delay                                                                              
[00:00:03.116,180] <dbg> bt_mesh_adv.bt_mesh_scan_enable:                                                                                        
[00:00:03.116,455] <dbg> bt_mesh_adv.adv_send: Advertising stopped                                                                               
[00:00:03.122,100] <err> bt_mesh_adv: starting scan failed (err -5)                                                                              
[00:00:03.122,100] <dbg> bt_mesh_lpn.lpn_set_state: recv delay -> wait update                                                                    
[00:00:03.471,252] <dbg> bt_mesh_lpn.lpn_timeout: state: wait update                                                                             
[00:00:03.471,282] <wrn> bt_mesh_lpn: No response from Friend during ReceiveWindow                                                               
[00:00:03.471,282] <dbg> bt_mesh_adv.bt_mesh_scan_disable:                                                                                       
[00:00:03.471,282] <dbg> bt_mesh_lpn.lpn_set_state: wait update -> established                                                                   
[00:00:03.571,350] <dbg> bt_mesh_lpn.lpn_timeout: state: established                                                                             
[00:00:03.571,350] <dbg> bt_mesh_lpn.sub_update: op 0x07 sent_req 0x00                                                                           
[00:00:03.571,502] <dbg> bt_mesh_adv.bt_mesh_adv_send: type 0x01 len 21: 6863b4482c9f145cf3a426b87b388fc~                                        
[00:00:03.571,563] <dbg> bt_mesh_adv.adv_send: type 1 len 21: 6863b4482c9f145cf3a426b87b388fc~                                                   
[00:00:03.571,563] <dbg> bt_mesh_adv.adv_send: count 2 interval 20ms duration 90ms                                                               
[00:00:03.572,113] <dbg> bt_mesh_lpn.req_sent: req 0x07 duration 90 err 0 state established                                                      
[00:00:03.572,143] <dbg> bt_mesh_lpn.lpn_set_state: established -> recv delay                                                                    
[00:00:03.572,143] <dbg> bt_mesh_adv.adv_send: Advertising started. Sleeping 90 ms                                                                                                        
[00:00:03.662,231] <dbg> bt_mesh_lpn.lpn_timeout: state: recv delay                                                                              
[00:00:03.662,231] <dbg> bt_mesh_adv.bt_mesh_scan_enable:                                                                                        
[00:00:03.662,506] <dbg> bt_mesh_adv.adv_send: Advertising stopped                                                                               
[00:00:03.668,151] <err> bt_mesh_adv: starting scan failed (err -5)                                                                              
[00:00:03.668,151] <dbg> bt_mesh_lpn.lpn_set_state: recv delay -> wait update                                                                    
[00:00:04.017,303] <dbg> bt_mesh_lpn.lpn_timeout: state: wait update                                                                             
[00:00:04.017,333] <wrn> bt_mesh_lpn: No response from Friend during ReceiveWindow                                                               
[00:00:04.017,333] <dbg> bt_mesh_adv.bt_mesh_scan_disable:                                                                                       
[00:00:04.017,333] <dbg> bt_mesh_lpn.lpn_set_state: wait update -> established                                                                   
[00:00:04.117,401] <dbg> bt_mesh_lpn.lpn_timeout: state: established                                                                             
[00:00:04.117,401] <err> bt_mesh_lpn: No response from Friend after 4 retries                                                                    
[00:00:04.117,401] <dbg> bt_mesh_lpn.clear_friendship: force 0 disable 0                                                                         
[00:00:04.117,431] <dbg> bt_mesh_lpn.send_friend_clear:                                                                                          
[00:00:04.117,553] <dbg> bt_mesh_adv.bt_mesh_adv_send: type 0x01 len 22: 37a1d5a5a62bf5bc5b4f6ab021e2f97~                                        
[00:00:04.117,614] <dbg> bt_mesh_adv.adv_send: type 1 len 22: 37a1d5a5a62bf5bc5b4f6ab021e2f97~                                                   
[00:00:04.117,645] <dbg> bt_mesh_adv.adv_send: count 3 interval 20ms duration 120ms                                                              
[00:00:04.118,194] <dbg> bt_mesh_adv.adv_send: Advertising started. Sleeping 120 ms                                                              
[00:00:04.238,494] <dbg> bt_mesh_adv.bt_mesh_scan_enable:                                                                                        
[00:00:04.238,830] <dbg> bt_mesh_lpn.lpn_set_state: established -> clear                                                                         
[00:00:04.238,861] <dbg> bt_mesh_adv.adv_send: Advertising stopped                                                                               
[00:00:05.338,928] <dbg> bt_mesh_lpn.lpn_timeout: state: clear                                                                                   
[00:00:05.338,958] <dbg> bt_mesh_lpn.clear_friendship: force 0 disable 0                                                                         
[00:00:05.338,958] <dbg> bt_mesh_lpn.send_friend_clear:                                                                                          
[00:00:05.339,080] <dbg> bt_mesh_adv.bt_mesh_adv_send: type 0x01 len 22: 3754d338cb5ea322ab687a2cce7ed7d~                                        
[00:00:05.339,141] <dbg> bt_mesh_adv.adv_send: type 1 len 22: 3754d338cb5ea322ab687a2cce7ed7d~                                                   
[00:00:05.339,172] <dbg> bt_mesh_adv.adv_send: count 3 interval 20ms duration 120ms                                                              
[00:00:05.339,782] <dbg> bt_mesh_adv.adv_send: Advertising started. Sleeping 120 ms                                                              
[00:00:05.398,559] <dbg> bt_mesh_adv.bt_mesh_scan_cb: len 24: 172a377b396324503cc9f2135618b54~                                                                                                                
[00:00:05.398,681] <wrn> bt_mesh_transport: Ignoring unexpected message in Low Power mode                                                        
[00:00:05.398,681] <wrn> bt_mesh_net: Removing rejected message from Network Message Cache                                                       
[00:00:05.422,546] <dbg> bt_mesh_adv.bt_mesh_scan_cb: len 24: 172a377b396324503cc9f2135618b54~                                                   
[00:00:05.447,143] <dbg> bt_mesh_adv.bt_mesh_scan_cb: len 24: 172a377b396324503cc9f2135618b54~                                                   
[00:00:05.460,021] <dbg> bt_mesh_adv.bt_mesh_scan_enable:                                                                                        
[00:00:05.460,906] <dbg> bt_mesh_lpn.lpn_set_state: clear -> clear                                                                             
[00:00:05.460,906] <dbg> bt_mesh_adv.adv_send: Advertising stopped                                                                               
[00:00:06.381,774] <dbg> bt_mesh_adv.bt_mesh_scan_cb: len 31: 1eff4c00121900efb45e5718bbad3e0~                                                   
[00:00:06.560,974] <dbg> bt_mesh_lpn.lpn_timeout: state: clear                                                                                   
[00:00:06.560,974] <dbg> bt_mesh_lpn.clear_friendship: force 0 disable 0                                                                         
[00:00:06.561,004] <dbg> bt_mesh_lpn.lpn_set_state: clear -> enabled                                                                             
[00:00:07.384,246] <dbg> bt_mesh_adv.bt_mesh_scan_cb: len 31: 1eff4c00121900efb45e5718bbad3e0~                                                   
[00:00:08.561,065] <dbg> bt_mesh_lpn.lpn_timeout: state: enabled                                                                                 
[00:00:08.561,096] <dbg> bt_mesh_lpn.send_friend_req:                                                                                            
[00:00:08.561,248] <dbg> bt_mesh_adv.bt_mesh_adv_send: type 0x01 len 28: 37477c9eda767ac90b7e12c81e9b436~                                        
[00:00:08.561,309] <dbg> bt_mesh_adv.adv_send: type 1 len 28: 37477c9eda767ac90b7e12c81e9b436~                                                   
[00:00:08.561,309] <dbg> bt_mesh_adv.adv_send: count 2 interval 20ms duration 90ms                                                               
[00:00:08.562,042] <dbg> bt_mesh_lpn.lpn_set_state: enabled -> wait offer                                                                        
[00:00:08.562,042] <dbg> bt_mesh_adv.adv_send: Advertising started. Sleeping 90 ms                                                               
[00:00:08.652,313] <dbg> bt_mesh_adv.adv_send: Advertising stopped                                                                               
[00:00:08.888,031] <dbg> bt_mesh_adv.bt_mesh_scan_cb: len 31: 1eff4c00121900efb45e5718bbad3e0~                                                   
[00:00:09.212,158] <dbg> bt_mesh_adv.bt_mesh_scan_cb: len 26: 192a37461ac77de88f099991f4088e5~                                                   
[00:00:09.212,280] <dbg> bt_mesh_lpn.bt_mesh_lpn_friend_offer: recv_win 255 queue_size 16 sub_list_size 3 rssi -39 counter 1                     
[00:00:09.214,782] <dbg> bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00                                                                        
[00:00:09.214,904] <dbg> bt_mesh_adv.bt_mesh_adv_send: type 0x01 len 19: <log_strdup alloc failed>                                               
[00:00:09.214,965] <dbg> bt_mesh_adv.adv_send: type 1 len 19: <log_strdup alloc failed>                                                          
[00:00:09.214,965] <dbg> bt_mesh_adv.adv_send: count 2 interval 20ms duration 90ms                                                               
[00:00:09.215,606] <dbg> bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait offer                                                       
[00:00:09.215,637] <dbg> bt_mesh_adv.adv_send: Advertising started. Sleeping 90 ms                                                               
[00:00:09.305,847] <dbg> bt_mesh_adv.adv_send: Advertising stopped                                                                               
[00:00:09.415,008] <dbg> bt_mesh_adv.bt_mesh_scan_cb: len 26: 192a605c3bb3ae4dc1980dd4dd99b86~                                                   
[00:00:09.415,130] <inf> bt_mesh_lpn: Friendship established with 0x0001                                                                         
[00:00:09.415,161] <dbg> bt_mesh_lpn.friend_response_received: lpn->sent_req 0x01                                                                
[00:00:09.415,161] <dbg> bt_mesh_adv.bt_mesh_scan_disable:                                                                                       
[00:00:09.415,405] <dbg> bt_mesh_lpn.lpn_set_state: wait offer -> established                                                                    

Environment (please complete the following information):

  • Zephyr project in nRF52840 boards

Additional context
Tracking the error, it is generated, apparently, in hci_core.c, when the function "start_le_scan(u8_t scan_type, u16_t interval, u16_t window)" uses the "err = set_random_address(&bt_dev.id_addr[0].a);" function.

@DHortelano DHortelano added the bug The issue is a bug, or the PR is fixing a bug label Jan 22, 2020
@aescolar
Copy link
Member

CC @jhedberg

@aurel32
Copy link
Collaborator

aurel32 commented Jan 22, 2020

@DHortelano, what configuration values do you use for BT_MESH_LPN_RECV_DELAY and BT_MESH_LPN_SCAN_LATENCY. To get it working on a nRF52 device, I had to increase BT_MESH_LPN_RECV_DELAY to 150 and keep BT_MESH_LPN_SCAN_LATENCY to the default 10.

I am not sure what should be the exact values, it seems that the error happens when the scanning phase starts too close to the end of the advertisement phase, although I haven't really debugged more than testing different values.

@jhedberg
Copy link
Member

CC @trond-snekvik

@DHortelano
Copy link
Author

Hi @aurel32, I used BT_MESH_LPN_RECV_DELAY=100 and CONFIG_BT_MESH_LPN_SCAN_LATENCY=10. I have tried to increase the BT_MESH_LPN_RECV_DELAY to 150, and you are right, it works fine, thank you!

it seems that the error happens when the scanning phase starts too close to the end of the advertisement phase,

I completely agree with you, and I think it could be due to the change of address type when the scan starts. I have added a check to do that only when the scan_type is BT_HCI_LE_SCAN_ACTIVE. This also works, and it allows to use a shorter BT_MESH_LPN_RECV_DELAY (I tried 50). However, I don't know if this modification is allowed by the Bluetooth Mesh standard...

@jhedberg
Copy link
Member

It sounds like this is all related to the fact that we don't have super precise control of advertising timing due to our use of standard HCI (and legacy 4.0 HCI at that). This should all hopefully get fixed once we start using Mesh vendor extensions for HCI. Meanwhile, the only thing I can think of improving is to change the default values of these Kconfig options.

@trond-snekvik
Copy link
Contributor

Looks like this is just a symptom of a bug in hci_core. I made a PR for skipping the address setting when using a passive scanner, like in the mesh, as it's not used. This should remove the call generating the error. @joerchan plans on fixing the overarching problem in his AE work.

@DHortelano #22313 should fix the problem, even for your original timing parameters.

@joerchan
Copy link
Contributor

@joerchan plans on fixing the overarching problem in his AE work.

To clarify, this problem can be avoided if the controller supports AE :) It is still something we have to deal with when AE commands are not available.

joerchan pushed a commit to trond-snekvik/zephyr that referenced this issue Jan 31, 2020
When privacy is disabled by default the scanner still protects it's
identity with the use of NRPA addresses. We should not set the identity
address for the passive scanner unless the Kconfig option to scan with
the identity has been enabled.

This makes passive scanner behave the same way as an active scanner
since none of them will report directed advertising reports towards
the scanners identity.

This also enables the advertiser to switch out the random address which
is needed for the Bluetooth Mesh LPN case.

Fixes zephyrproject-rtos#22088.

Signed-off-by: Trond Einar Snekvik <[email protected]>
jhedberg pushed a commit that referenced this issue Feb 3, 2020
When privacy is disabled by default the scanner still protects it's
identity with the use of NRPA addresses. We should not set the identity
address for the passive scanner unless the Kconfig option to scan with
the identity has been enabled.

This makes passive scanner behave the same way as an active scanner
since none of them will report directed advertising reports towards
the scanners identity.

This also enables the advertiser to switch out the random address which
is needed for the Bluetooth Mesh LPN case.

Fixes #22088.

Signed-off-by: Trond Einar Snekvik <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area: Bluetooth Mesh area: Bluetooth bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants