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.

Sign up for GitHub

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

Jump to bottom

Bluetooth mesh : LPN doesn't receive messages from Friend #32033

Closed
4ayo opened this issue Feb 5, 2021 · 3 comments · Fixed by #32080
Closed

Bluetooth mesh : LPN doesn't receive messages from Friend #32033

4ayo opened this issue Feb 5, 2021 · 3 comments · Fixed by #32080
Assignees
@jhedberg @trond-snekvik
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

@4ayo
Copy link

4ayo commented Feb 5, 2021

Describe the bug
I'm trying to set up a Friend and LPN with nRF52840 boards. The code is based on onoff-app sample.

Each time the LPN polls a message from Friend, which isn't linked to provisionment or node configuration, the message is dropped with a warning saying it's too short.

To Reproduce
Use onoff-app sample.

The Kconfig is the following one for the LPN :

CONFIG_BT_DEVICE_NAME="Zephyr LPN"
CONFIG_BT_MESH=y
CONFIG_BT_MESH_RELAY=n
CONFIG_BT_MESH_RELAY_ENABLED=n
CONFIG_BT_MESH_BEACON_ENABLED=n
CONFIG_BT_MESH_FRIEND=n
CONFIG_BT_MESH_LOW_POWER=y
CONFIG_BT_MESH_DEBUG=y
CONFIG_BT_MESH_DEBUG_LOW_POWER=y
# Other have default value

The Kconfig is the following one for the Friend :

CONFIG_BT_DEVICE_NAME="Zephyr Friend"
CONFIG_BT_MESH=y
CONFIG_BT_MESH_RELAY=n
CONFIG_BT_MESH_RELAY_ENABLED=n
CONFIG_BT_MESH_BEACON_ENABLED=n
CONFIG_BT_MESH_LOW_POWER=n
CONFIG_BT_MESH_FRIEND=y
CONFIG_BT_MESH_FRIEND_ENABLED=y
CONFIG_BT_MESH_FRIEND_QUEUE_SIZE=16
CONFIG_BT_MESH_DEBUG=y
CONFIG_BT_MESH_DEBUG_FRIEND=y
# Other have default value

The provisionment is done with the nRF mesh app. They are configured as follow (first LPN, next Friend) :
LPN :

  • Generic On Off server of first element : subscription address == group 0xC000
  • Generic On Off client of first element : publication address == group 0xC000

Friend

  • Generic On Off server of first element : subscription address == group 0xC000
  • Generic On Off client of first element : publication address == group 0xC000

Other parameters are let as is (default value).

Logs and console output

  • First scenario : pressing button from the LPN. The LED of Friend turns on, then he enqueues a message. At next poll, LPN is unable to read paquet (warning that the packet is too short, hence dropped). The friendship is momentarily broken and established again after a while.
Log of LPN

button_press_cnt 0x00
button_press_cnt 0x01 onoff_state 0x01
publish to 0xc000 onoff 0x0001 sw_idx 0x0000
gen_onoff_set
addr 0x08 state 0x01
addr 0x0008 onoff 0x01
Node 0x0008 OnOff status from 0x0008 with state 0x01
gen_onoff_set
addr 0x08 state 0x01
addr 0x0008 onoff 0x01
Node 0x0008 OnOff status from 0x0008 with state 0x01
[00:09:13.146,270] bt_mesh_lpn.lpn_timeout: state: established
[00:09:13.146,270] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:09:13.147,003] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state established
[00:09:13.147,003] bt_mesh_lpn.lpn_set_state: established -> recv delay
[00:09:13.237,091] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:09:13.238,891] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:09:13.592,163] bt_mesh_lpn.lpn_timeout: state: wait update
[00:09:13.592,163] bt_mesh_lpn: No response from Friend during ReceiveWindow
[00:09:13.592,407] bt_mesh_lpn.lpn_set_state: wait update -> established
[00:09:13.692,474] bt_mesh_lpn.lpn_timeout: state: established
[00:09:13.692,474] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:09:13.693,237] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state established
[00:09:13.693,237] bt_mesh_lpn.lpn_set_state: established -> recv delay
[00:09:13.784,210] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:09:13.784,484] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:09:13.850,311] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:13.850,341] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:13.876,098] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:13.876,098] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:13.903,533] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:13.903,564] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:14.139,282] bt_mesh_lpn.lpn_timeout: state: wait update
[00:09:14.139,282] bt_mesh_lpn: No response from Friend during ReceiveWindow
[00:09:14.139,526] bt_mesh_lpn.lpn_set_state: wait update -> established
[00:09:14.239,593] bt_mesh_lpn.lpn_timeout: state: established
[00:09:14.239,593] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:09:14.240,356] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state established
[00:09:14.240,356] bt_mesh_lpn.lpn_set_state: established -> recv delay
[00:09:14.331,329] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:09:14.331,726] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:09:14.397,430] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:14.397,460] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:14.426,605] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:14.426,635] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:14.447,784] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:14.447,784] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:14.686,401] bt_mesh_lpn.lpn_timeout: state: wait update
[00:09:14.686,401] bt_mesh_lpn: No response from Friend during ReceiveWindow
[00:09:14.686,614] bt_mesh_lpn.lpn_set_state: wait update -> established
[00:09:14.786,712] bt_mesh_lpn.lpn_timeout: state: established
[00:09:14.786,712] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:09:14.787,475] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state established
[00:09:14.787,475] bt_mesh_lpn.lpn_set_state: established -> recv delay
[00:09:14.877,563] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:09:14.879,333] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:09:14.943,878] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:14.943,908] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:14.974,182] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:14.974,212] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:14.994,232] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:14.994,262] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:15.232,635] bt_mesh_lpn.lpn_timeout: state: wait update
[00:09:15.232,635] bt_mesh_lpn: No response from Friend during ReceiveWindow
[00:09:15.232,849] bt_mesh_lpn.lpn_set_state: wait update -> established
[00:09:15.332,946] bt_mesh_lpn.lpn_timeout: state: established
[00:09:15.332,946] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:09:15.333,709] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state established
[00:09:15.333,709] bt_mesh_lpn.lpn_set_state: established -> recv delay
[00:09:15.424,682] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:09:15.424,957] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:09:15.490,814] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:15.490,844] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:15.520,080] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:15.520,111] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:15.779,754] bt_mesh_lpn.lpn_timeout: state: wait update
[00:09:15.779,754] bt_mesh_lpn: No response from Friend during ReceiveWindow
[00:09:15.779,998] bt_mesh_lpn.lpn_set_state: wait update -> established
[00:09:15.880,065] bt_mesh_lpn.lpn_timeout: state: established
[00:09:15.880,065] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:09:15.880,767] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state established
[00:09:15.880,950] bt_mesh_lpn.lpn_set_state: established -> recv delay
[00:09:15.971,038] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:09:15.972,167] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:09:16.037,475] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:16.037,506] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:16.062,988] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:16.063,018] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:16.091,217] bt_mesh_net: Dropping too short mesh packet (len 17)
[00:09:16.091,247] bt_mesh_net: 0007000020000c000846ab010ec4208~
[00:09:16.326,110] bt_mesh_lpn.lpn_timeout: state: wait update
[00:09:16.326,110] bt_mesh_lpn: No response from Friend during ReceiveWindow
[00:09:16.326,354] bt_mesh_lpn.lpn_set_state: wait update -> established
[00:09:16.426,422] bt_mesh_lpn.lpn_timeout: state: established
[00:09:16.426,422] bt_mesh_lpn: No response from Friend after 6 retries
[00:09:16.426,452] bt_mesh_lpn.clear_friendship: force 0 disable 0
[00:09:16.426,452] bt_mesh_lpn.send_friend_clear:
[00:09:16.547,363] bt_mesh_lpn.lpn_set_state: established -> clear
[00:09:17.647,430] bt_mesh_lpn.lpn_timeout: state: clear
[00:09:17.647,430] bt_mesh_lpn.clear_friendship: force 0 disable 0
[00:09:17.647,460] bt_mesh_lpn.send_friend_clear:
[00:09:17.768,371] bt_mesh_lpn.lpn_set_state: clear -> clear
[00:09:18.868,438] bt_mesh_lpn.lpn_timeout: state: clear
[00:09:18.868,438] bt_mesh_lpn.clear_friendship: force 0 disable 0
[00:09:18.868,469] bt_mesh_lpn.send_friend_clear:
[00:09:18.989,379] bt_mesh_lpn.lpn_set_state: clear -> clear
[00:09:20.089,447] bt_mesh_lpn.lpn_timeout: state: clear
[00:09:20.089,447] bt_mesh_lpn.clear_friendship: force 0 disable 0
[00:09:20.089,477] bt_mesh_lpn.lpn_set_state: clear -> enabled
[00:09:28.089,538] bt_mesh_lpn.lpn_timeout: state: enabled
[00:09:28.089,538] bt_mesh_lpn.send_friend_req:
[00:09:28.090,270] bt_mesh_lpn.lpn_set_state: enabled -> req wait
[00:09:28.190,338] bt_mesh_lpn.lpn_timeout: state: req wait
[00:09:28.190,734] bt_mesh_lpn.lpn_set_state: req wait -> wait offer
[00:09:28.390,899] bt_mesh_lpn.bt_mesh_lpn_friend_offer: recv_win 255 queue_size 16 sub_list_size 3 rssi -37 co1
[00:09:28.393,218] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:09:28.394,927] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait offer
[00:09:28.394,958] bt_mesh_lpn.lpn_set_state: wait offer -> recv delay
[00:09:28.486,419] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:09:28.486,572] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:09:28.841,644] bt_mesh_lpn.lpn_timeout: state: wait update
[00:09:28.841,888] bt_mesh_lpn: Retrying first Friend Poll
[00:09:28.841,888] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:09:28.842,590] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait update
[00:09:28.842,590] bt_mesh_lpn.lpn_set_state: wait update -> recv delay
[00:09:28.932,708] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:09:28.934,509] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:09:29.287,780] bt_mesh_lpn.lpn_timeout: state: wait update
[00:09:29.287,994] bt_mesh_lpn: Retrying first Friend Poll
[00:09:29.288,024] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:09:29.288,726] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait update
[00:09:29.288,726] bt_mesh_lpn.lpn_set_state: wait update -> recv delay
[00:09:29.378,814] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:09:29.380,615] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:09:29.733,886] bt_mesh_lpn.lpn_timeout: state: wait update
[00:09:29.734,130] bt_mesh_lpn: Retrying first Friend Poll
[00:09:29.734,130] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:09:29.734,832] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait update
[00:09:29.734,832] bt_mesh_lpn.lpn_set_state: wait update -> recv delay
[00:09:29.824,920] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:09:29.826,721] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:09:30.179,992] bt_mesh_lpn.lpn_timeout: state: wait update
[00:09:30.180,206] bt_mesh_lpn: Retrying first Friend Poll
[00:09:30.180,236] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:09:30.180,938] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait update
[00:09:30.180,938] bt_mesh_lpn.lpn_set_state: wait update -> recv delay
[00:09:30.271,026] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:09:30.272,827] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:09:30.626,098] bt_mesh_lpn.lpn_timeout: state: wait update
[00:09:30.626,342] bt_mesh_lpn: Retrying first Friend Poll
[00:09:30.626,342] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:09:30.627,044] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait update
[00:09:30.627,044] bt_mesh_lpn.lpn_set_state: wait update -> recv delay
[00:09:30.718,017] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:09:30.718,566] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:09:31.073,089] bt_mesh_lpn.lpn_timeout: state: wait update
[00:09:31.073,303] bt_mesh_lpn: Timed out waiting for first Friend Update
[00:09:31.073,333] bt_mesh_lpn.clear_friendship: force 0 disable 0
[00:09:31.073,333] bt_mesh_lpn.lpn_set_state: wait update -> enabled
[00:09:39.073,394] bt_mesh_lpn.lpn_timeout: state: enabled
[00:09:39.073,394] bt_mesh_lpn.send_friend_req:
[00:09:39.074,127] bt_mesh_lpn.lpn_set_state: enabled -> req wait
[00:09:39.174,194] bt_mesh_lpn.lpn_timeout: state: req wait
[00:09:39.174,591] bt_mesh_lpn.lpn_set_state: req wait -> wait offer
[00:09:39.369,415] bt_mesh_lpn.bt_mesh_lpn_friend_offer: recv_win 255 queue_size 16 sub_list_size 3 rssi -31 co0
[00:09:39.371,765] bt_mesh_lpn.send_fr+-----------------------------+
[00:09:39.373,352] bt_mesh_lpn.req_sen| |tate wait offer
[00:09:39.373,352] bt_mesh_lpn.lpn_set| Cannot open /dev/ttyACM1! |y
[00:09:39.463,439] bt_mesh_lpn.lpn_tim| |
[00:09:39.463,470] bt_mesh_lpn.lpn_set+-----------------------------+te
[00:09:39.531,158] bt_mesh_lpn: Friendship established with 0x000c

Log of friend

gen_onoff_set
addr 0x0c state 0x01
addr 0x000c onoff 0x01
gen_onoff_set
addr 0x0c state 0x01
addr 0x000c onoff 0x01
[00:09:24.112,609] bt_mesh_friend.bt_mesh_friend_match: LPN 0x0008 matched address 0xc000
[00:09:24.118,041] bt_mesh_friend.bt_mesh_friend_match: LPN 0x0008 matched address 0x0008
[00:09:24.118,072] bt_mesh_friend.bt_mesh_friend_enqueue_tx: net_idx 0x0000 dst 0x0008 src 0x000c
[00:09:24.118,072] bt_mesh_friend.friend_lpn_enqueue_tx: LPN 0x0008
[00:09:24.118,103] bt_mesh_friend.enqueue_friend_pdu: type 0
[00:09:24.118,103] bt_mesh_friend.friend_lpn_enqueue_tx: Queued message for LPN 0x0008
[00:09:24.118,133] bt_mesh_friend.bt_mesh_friend_enqueue_rx: recv_ttl 7 net_idx 0x0000 src 0x0008 dst 0xc000
[00:09:24.333,679] bt_mesh_friend.bt_mesh_friend_match: LPN 0x0008 matched address 0xc000
[00:09:24.339,111] bt_mesh_friend.bt_mesh_friend_match: LPN 0x0008 matched address 0x0008
[00:09:24.339,141] bt_mesh_friend.bt_mesh_friend_enqueue_tx: net_idx 0x0000 dst 0x0008 src 0x000c
[00:09:24.339,141] bt_mesh_friend.friend_lpn_enqueue_tx: LPN 0x0008
[00:09:24.339,172] bt_mesh_friend.enqueue_friend_pdu: type 0
[00:09:24.339,172] bt_mesh_friend.friend_lpn_enqueue_tx: Queued message for LPN 0x0008
[00:09:24.339,202] bt_mesh_friend.bt_mesh_friend_enqueue_rx: recv_ttl 7 net_idx 0x0000 src 0x0008 dst 0xc000
[00:09:28.657,440] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:28.657,470] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:28.657,470] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 1 frnd->fsn 0
[00:09:28.657,501] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:09:28.808,532] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 0 last (nil)
[00:09:28.808,532] bt_mesh_app_keys: Unknown AppKey 0x002
[00:09:29.203,643] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:29.203,674] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:29.203,674] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 1 frnd->fsn 1
[00:09:29.203,674] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:09:29.203,704] bt_mesh_friend.bt_mesh_friend_poll: Re-sending last PDU
[00:09:29.354,736] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x2000839c
[00:09:29.354,766] bt_mesh_friend.friend_timeout: Sending frnd->last 0x2000839c
[00:09:29.355,224] bt_mesh_friend.buf_send_start: err 0
[00:09:29.415,863] bt_mesh_friend.buf_send_end: err 0
[00:09:29.415,863] bt_mesh_friend.buf_send_end: Waiting 30000 ms for next poll
[00:09:29.750,762] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:29.750,762] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:29.750,793] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 1 frnd->fsn 1
[00:09:29.750,793] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:09:29.750,793] bt_mesh_friend.bt_mesh_friend_poll: Re-sending last PDU
[00:09:29.901,855] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x2000839c
[00:09:29.901,855] bt_mesh_friend.friend_timeout: Sending frnd->last 0x2000839c
[00:09:29.902,343] bt_mesh_friend.buf_send_start: err 0
[00:09:29.962,982] bt_mesh_friend.buf_send_end: err 0
[00:09:29.963,134] bt_mesh_friend.buf_send_end: Waiting 30000 ms for next poll
[00:09:30.297,882] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:30.297,882] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:30.297,882] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 1 frnd->fsn 1
[00:09:30.297,912] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:09:30.297,912] bt_mesh_friend.bt_mesh_friend_poll: Re-sending last PDU
[00:09:30.448,974] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x2000839c
[00:09:30.448,974] bt_mesh_friend.friend_timeout: Sending frnd->last 0x2000839c
[00:09:30.449,462] bt_mesh_friend.buf_send_start: err 0
[00:09:30.510,101] bt_mesh_friend.buf_send_end: err 0
[00:09:30.510,101] bt_mesh_friend.buf_send_end: Waiting 30000 ms for next poll
[00:09:30.844,085] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:30.844,116] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:30.844,116] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 1 frnd->fsn 1
[00:09:30.844,146] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:09:30.844,146] bt_mesh_friend.bt_mesh_friend_poll: Re-sending last PDU
[00:09:30.995,208] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x2000839c
[00:09:30.995,239] bt_mesh_friend.friend_timeout: Sending frnd->last 0x2000839c
[00:09:30.995,697] bt_mesh_friend.buf_send_start: err 0
[00:09:31.056,396] bt_mesh_friend.buf_send_end: err 0
[00:09:31.056,396] bt_mesh_friend.buf_send_end: Waiting 30000 ms for next poll
[00:09:31.390,777] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:31.390,777] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:31.390,777] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 1 frnd->fsn 1
[00:09:31.390,808] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:09:31.390,808] bt_mesh_friend.bt_mesh_friend_poll: Re-sending last PDU
[00:09:31.541,870] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x2000839c
[00:09:31.541,900] bt_mesh_friend.friend_timeout: Sending frnd->last 0x2000839c
[00:09:31.542,358] bt_mesh_friend.buf_send_start: err 0
[00:09:31.602,996] bt_mesh_friend.buf_send_end: err 0
[00:09:31.603,118] bt_mesh_friend.buf_send_end: Waiting 30000 ms for next poll
[00:09:31.937,164] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:31.937,194] bt_mesh_friend.bt_mesh_friend_clear: LPN addr 0x0008 counter 0x0003
[00:09:31.937,194] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:31.937,225] bt_mesh_friend.bt_mesh_friend_match: LPN 0x0008 matched address 0x0008
[00:09:31.937,225] bt_mesh_friend.bt_mesh_friend_enqueue_tx: net_idx 0x0000 dst 0x0008 src 0x000c
[00:09:31.937,255] bt_mesh_friend.friend_lpn_enqueue_tx: LPN 0x0008
[00:09:31.937,255] bt_mesh_friend.enqueue_friend_pdu: type 0
[00:09:31.937,286] bt_mesh_friend.friend_lpn_enqueue_tx: Queued message for LPN 0x0008
[00:09:31.937,286] bt_mesh_friend.friend_clear: LPN 0x0008
[00:09:33.158,538] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:33.158,569] bt_mesh_friend.bt_mesh_friend_clear: LPN addr 0x0008 counter 0x0003
[00:09:33.158,599] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:33.158,599] bt_mesh_friend: No matching LPN addr 0x0008
[00:09:34.379,150] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:34.379,180] bt_mesh_friend.bt_mesh_friend_clear: LPN addr 0x0008 counter 0x0003
[00:09:34.379,180] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:34.379,180] bt_mesh_friend: No matching LPN addr 0x0008
[00:09:43.601,043] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0xfffd
[00:09:43.601,104] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:43.603,515] bt_mesh_friend.bt_mesh_friend_req: LPN 0x0008 rssi -37 recv_delay 100 poll_to 30000ms
[00:09:43.603,515] bt_mesh_friend.offer_delay: ReceiveWindowFactor 10 ReceiveWindow 255 RSSIFactor 10 RSSI -37
[00:09:43.603,546] bt_mesh_friend.offer_delay: Local Delay calculated as 292 ms
[00:09:43.603,546] bt_mesh_friend.enqueue_offer:
[00:09:43.603,546] bt_mesh_friend.encode_friend_ctl: LPN 0x0008
[00:09:43.895,629] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x200083b4
[00:09:43.895,629] bt_mesh_friend.friend_timeout: Sending frnd->last 0x200083b4
[00:09:43.896,118] bt_mesh_friend.buf_send_start: err 0
[00:09:43.935,302] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:43.935,302] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:43.935,302] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 0 frnd->fsn 0
[00:09:43.935,333] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:09:43.935,333] bt_mesh_friend.bt_mesh_friend_poll: Friendship established with 0x0008
[00:09:43.935,333] bt_mesh_friend.encode_update: lpn 0x0008 md 0x00
[00:09:43.935,363] bt_mesh_friend.encode_friend_ctl: LPN 0x0008
[00:09:43.935,363] bt_mesh_friend.bt_mesh_friend_poll: Enqueued Friend Update to empty queue
[00:09:43.956,787] bt_mesh_friend.buf_send_end: err 0
[00:09:43.956,787] bt_mesh_friend: Another request before previous completed sending
[00:09:44.086,395] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 0 last (nil)
[00:09:44.086,425] bt_mesh_friend: Friendship not established with 0x0008
[00:09:44.086,425] bt_mesh_friend.friend_clear: LPN 0x0008
[00:09:44.352,783] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:44.352,783] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:44.352,813] bt_mesh_friend: No matching LPN addr 0x0008
[00:09:44.799,255] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:44.799,255] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:44.799,285] bt_mesh_friend: No matching LPN addr 0x0008
[00:09:45.245,391] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:45.245,391] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:45.245,391] bt_mesh_friend: No matching LPN addr 0x0008
[00:09:45.691,467] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:45.691,467] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:45.691,467] bt_mesh_friend: No matching LPN addr 0x0008
[00:09:46.136,840] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:09:46.136,871] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:09:46.136,871] bt_mesh_friend: No matching LPN addr 0x0008
[00:00:02.356,201] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0xfffd
[00:00:02.356,262] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:00:02.358,581] bt_mesh_friend.bt_mesh_friend_req: LPN 0x0008 rssi -31 recv_delay 100 poll_to 30000ms
[00:00:02.358,581] bt_mesh_friend.offer_delay: ReceiveWindowFactor 10 ReceiveWindow 255 RSSIFactor 10 RSSI -31
[00:00:02.358,581] bt_mesh_friend.offer_delay: Local Delay calculated as 286 ms
[00:00:02.358,612] bt_mesh_friend.enqueue_offer:
[00:00:02.358,612] bt_mesh_friend.encode_friend_ctl: LPN 0x0008
[00:00:02.644,683] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x2000839c
[00:00:02.644,683] bt_mesh_friend.friend_timeout: Sending frnd->last 0x2000839c
[00:00:02.646,392] bt_mesh_friend.buf_send_start: err 0
[00:00:02.655,242] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:00:02.655,273] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:00:02.655,273] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 0 frnd->fsn 0
[00:00:02.655,303] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:00:02.655,303] bt_mesh_friend.bt_mesh_friend_poll: Friendship established with 0x0008

  • Second scenario : pressing button from the Friend. The LED of Friend turns on, then he enqueues a message. At next poll, LPN is unable to read paquet (warning that the packet is too short, hence dropped). The friendship is broken and they can't re-establish it. The LPN's LED remains turned off.
Log of LPN

[00:02:30.199,981] bt_mesh_lpn.lpn_timeout: state: established
[00:02:30.199,981] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:30.200,714] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state established
[00:02:30.200,714] bt_mesh_lpn.lpn_set_state: established -> recv delay
[00:02:30.290,802] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:30.292,602] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:30.645,874] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:30.645,874] bt_mesh_lpn: No response from Friend during ReceiveWindow
[00:02:30.646,118] bt_mesh_lpn.lpn_set_state: wait update -> established
[00:02:30.746,185] bt_mesh_lpn.lpn_timeout: state: established
[00:02:30.746,185] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:30.746,917] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state established
[00:02:30.747,100] bt_mesh_lpn.lpn_set_state: established -> recv delay
[00:02:30.838,073] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:30.838,348] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:31.193,145] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:31.193,145] bt_mesh_lpn: No response from Friend during ReceiveWindow
[00:02:31.193,389] bt_mesh_lpn.lpn_set_state: wait update -> established
[00:02:31.293,457] bt_mesh_lpn.lpn_timeout: state: established
[00:02:31.293,457] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:31.294,158] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state established
[00:02:31.294,342] bt_mesh_lpn.lpn_set_state: established -> recv delay
[00:02:31.384,429] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:31.385,559] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:31.739,501] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:31.739,501] bt_mesh_lpn: No response from Friend during ReceiveWindow
[00:02:31.739,746] bt_mesh_lpn.lpn_set_state: wait update -> established
[00:02:31.839,813] bt_mesh_lpn.lpn_timeout: state: established
[00:02:31.839,813] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:31.840,545] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state established
[00:02:31.840,545] bt_mesh_lpn.lpn_set_state: established -> recv delay
[00:02:31.930,633] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:31.932,434] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:32.285,705] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:32.285,705] bt_mesh_lpn: No response from Friend during ReceiveWindow
[00:02:32.285,919] bt_mesh_lpn.lpn_set_state: wait update -> established
[00:02:32.386,016] bt_mesh_lpn.lpn_timeout: state: established
[00:02:32.386,016] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:32.386,749] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state established
[00:02:32.386,779] bt_mesh_lpn.lpn_set_state: established -> recv delay
[00:02:32.476,867] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:32.478,637] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:32.831,939] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:32.831,939] bt_mesh_lpn: No response from Friend during ReceiveWindow
[00:02:32.832,183] bt_mesh_lpn.lpn_set_state: wait update -> established
[00:02:32.932,250] bt_mesh_lpn.lpn_timeout: state: established
[00:02:32.932,250] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:32.932,952] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state established
[00:02:32.932,952] bt_mesh_lpn.lpn_set_state: established -> recv delay
[00:02:33.023,925] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:33.024,475] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:33.378,997] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:33.378,997] bt_mesh_lpn: No response from Friend during ReceiveWindow
[00:02:33.379,241] bt_mesh_lpn.lpn_set_state: wait update -> established
[00:02:33.479,309] bt_mesh_lpn.lpn_timeout: state: established
[00:02:33.479,309] bt_mesh_lpn: No response from Friend after 6 retries
[00:02:33.479,339] bt_mesh_lpn.clear_friendship: force 0 disable 0
[00:02:33.479,339] bt_mesh_lpn.send_friend_clear:
[00:02:33.600,372] bt_mesh_lpn.lpn_set_state: established -> clear
[00:02:34.700,439] bt_mesh_lpn.lpn_timeout: state: clear
[00:02:34.700,439] bt_mesh_lpn.clear_friendship: force 0 disable 0
[00:02:34.700,469] bt_mesh_lpn.send_friend_clear:
[00:02:34.821,380] bt_mesh_lpn.lpn_set_state: clear -> clear
[00:02:35.921,447] bt_mesh_lpn.lpn_timeout: state: clear
[00:02:35.921,447] bt_mesh_lpn.clear_friendship: force 0 disable 0
[00:02:35.921,478] bt_mesh_lpn.send_friend_clear:
[00:02:36.042,388] bt_mesh_lpn.lpn_set_state: clear -> clear
[00:02:37.142,456] bt_mesh_lpn.lpn_timeout: state: clear
[00:02:37.142,456] bt_mesh_lpn.clear_friendship: force 0 disable 0
[00:02:37.142,486] bt_mesh_lpn.lpn_set_state: clear -> enabled
[00:02:45.142,547] bt_mesh_lpn.lpn_timeout: state: enabled
[00:02:45.142,547] bt_mesh_lpn.send_friend_req:
[00:02:45.143,463] bt_mesh_lpn.lpn_set_state: enabled -> req wait
[00:02:45.243,347] bt_mesh_lpn.lpn_timeout: state: req wait
[00:02:45.243,743] bt_mesh_lpn.lpn_set_state: req wait -> wait offer
[00:02:45.442,596] bt_mesh_lpn.bt_mesh_lpn_friend_offer: recv_win 255 queue_size 16 sub_list_size 3 rssi -35 co1
[00:02:45.444,915] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:45.446,624] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait offer
[00:02:45.446,655] bt_mesh_lpn.lpn_set_state: wait offer -> recv delay
[00:02:45.538,238] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:45.538,269] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:45.893,341] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:45.893,585] bt_mesh_lpn: Retrying first Friend Poll
[00:02:45.893,585] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:45.894,287] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait update
[00:02:45.894,287] bt_mesh_lpn.lpn_set_state: wait update -> recv delay
[00:02:45.984,405] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:45.986,206] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:46.339,477] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:46.339,691] bt_mesh_lpn: Retrying first Friend Poll
[00:02:46.339,721] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:46.340,423] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait update
[00:02:46.340,423] bt_mesh_lpn.lpn_set_state: wait update -> recv delay
[00:02:46.430,511] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:46.432,312] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:46.785,583] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:46.785,827] bt_mesh_lpn: Retrying first Friend Poll
[00:02:46.785,827] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:46.786,529] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait update
[00:02:46.786,529] bt_mesh_lpn.lpn_set_state: wait update -> recv delay
[00:02:46.876,617] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:46.878,417] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:47.231,689] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:47.231,903] bt_mesh_lpn: Retrying first Friend Poll
[00:02:47.231,933] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:47.232,635] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait update
[00:02:47.232,635] bt_mesh_lpn.lpn_set_state: wait update -> recv delay
[00:02:47.323,760] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:47.324,035] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:47.678,833] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:47.679,077] bt_mesh_lpn: Retrying first Friend Poll
[00:02:47.679,077] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:47.679,779] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait update
[00:02:47.679,779] bt_mesh_lpn.lpn_set_state: wait update -> recv delay
[00:02:47.769,866] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:47.771,667] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:48.124,938] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:48.125,152] bt_mesh_lpn: Timed out waiting for first Friend Update
[00:02:48.125,152] bt_mesh_lpn.clear_friendship: force 0 disable 0
[00:02:48.125,183] bt_mesh_lpn.lpn_set_state: wait update -> enabled
[00:02:56.125,244] bt_mesh_lpn.lpn_timeout: state: enabled
[00:02:56.125,244] bt_mesh_lpn.send_friend_req:
[00:02:56.125,976] bt_mesh_lpn.lpn_set_state: enabled -> req wait
[00:02:56.226,043] bt_mesh_lpn.lpn_timeout: state: req wait
[00:02:56.226,440] bt_mesh_lpn.lpn_set_state: req wait -> wait offer
[00:02:56.424,774] bt_mesh_lpn.bt_mesh_lpn_friend_offer: recv_win 255 queue_size 16 sub_list_size 3 rssi -34 co2
[00:02:56.427,093] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:56.428,771] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait offer
[00:02:56.428,771] bt_mesh_lpn.lpn_set_state: wait offer -> recv delay
[00:02:56.518,859] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:56.518,890] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:56.873,962] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:56.874,206] bt_mesh_lpn: Retrying first Friend Poll
[00:02:56.874,206] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:56.874,908] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait update
[00:02:56.874,908] bt_mesh_lpn.lpn_set_state: wait update -> recv delay
[00:02:56.965,026] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:56.966,827] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:57.320,098] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:57.320,312] bt_mesh_lpn: Retrying first Friend Poll
[00:02:57.320,343] bt_mesh_lpn.send_friend_poll: lpn->sent_req 0x00
[00:02:57.321,044] bt_mesh_lpn.req_sent: req 0x01 duration 90 err 0 state wait update
[00:02:57.321,044] bt_mesh_lpn.lpn_set_state: wait update -> recv delay
[00:02:57.411,163] bt_mesh_lpn.lpn_timeout: state: recv delay
[00:02:57.412,933] bt_mesh_lpn.lpn_set_state: recv delay -> wait update
[00:02:57.766,235] bt_mesh_lpn.lpn_timeout: state: wait update
[00:02:57.766,479] bt_mesh_lpn: Retrying first Friend Poll

Log of Friend

button_press_cnt 0x00
button_press_cnt 0x01 onoff_state 0x01
publish to 0xc000 onoff 0x0001 sw_idx 0x0000
gen_onoff_set
addr 0x0c state 0x01
addr 0x000c onoff 0x01
Node 0x000c OnOff status from 0x000c with state 0x01
gen_onoff_set
addr 0x0c state 0x01
addr 0x000c onoff 0x01
Node 0x000c OnOff status from 0x000c with state 0x01
[00:02:16.329,711] bt_mesh_friend.bt_mesh_friend_match: LPN 0x0008 matched address 0xc000
[00:02:16.329,742] bt_mesh_friend.bt_mesh_friend_enqueue_tx: net_idx 0x0000 dst 0xc000 src 0x000c
[00:02:16.329,742] bt_mesh_friend.friend_lpn_enqueue_tx: LPN 0x0008
[00:02:16.329,772] bt_mesh_friend.enqueue_friend_pdu: type 0
[00:02:16.329,772] bt_mesh_friend.friend_lpn_enqueue_tx: Queued message for LPN 0x0008
[00:02:16.330,780] bt_mesh_friend.bt_mesh_friend_match: LPN 0x0008 matched address 0xc000
[00:02:16.336,212] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:16.336,273] bt_mesh_friend.bt_mesh_friend_enqueue_rx: recv_ttl 7 net_idx 0x0000 src 0x000c dst 0xc000
[00:02:16.336,303] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:16.562,255] bt_mesh_friend.bt_mesh_friend_match: LPN 0x0008 matched address 0xc000
[00:02:16.562,286] bt_mesh_friend.bt_mesh_friend_enqueue_tx: net_idx 0x0000 dst 0xc000 src 0x000c
[00:02:16.562,286] bt_mesh_friend.friend_lpn_enqueue_tx: LPN 0x0008
[00:02:16.562,316] bt_mesh_friend.enqueue_friend_pdu: type 0
[00:02:16.562,316] bt_mesh_friend.friend_lpn_enqueue_tx: Queued message for LPN 0x0008
[00:02:16.563,232] bt_mesh_friend.bt_mesh_friend_match: LPN 0x0008 matched address 0xc000
[00:02:16.568,695] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:16.568,725] bt_mesh_friend.bt_mesh_friend_enqueue_rx: recv_ttl 7 net_idx 0x0000 src 0x000c dst 0xc000
[00:02:16.568,756] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:28.171,600] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:28.171,630] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:28.171,630] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 1 frnd->fsn 0
[00:02:28.171,661] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:02:28.322,723] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 0 last (nil)
[00:02:28.322,723] bt_mesh_app_keys: Unknown AppKey 0x002
[00:02:28.717,803] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:28.717,803] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:28.717,834] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 1 frnd->fsn 1
[00:02:28.717,834] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:02:28.717,864] bt_mesh_friend.bt_mesh_friend_poll: Re-sending last PDU
[00:02:28.868,927] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x2000839c
[00:02:28.868,957] bt_mesh_friend.friend_timeout: Sending frnd->last 0x2000839c
[00:02:28.870,544] bt_mesh_friend.buf_send_start: err 0
[00:02:28.931,243] bt_mesh_friend.buf_send_end: err 0
[00:02:28.931,274] bt_mesh_friend.buf_send_end: Waiting 30000 ms for next poll
[00:02:29.265,014] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:29.265,014] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:29.265,014] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 1 frnd->fsn 1
[00:02:29.265,045] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:02:29.265,045] bt_mesh_friend.bt_mesh_friend_poll: Re-sending last PDU
[00:02:29.416,107] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x2000839c
[00:02:29.416,107] bt_mesh_friend.friend_timeout: Sending frnd->last 0x2000839c
[00:02:29.417,724] bt_mesh_friend.buf_send_start: err 0
[00:02:29.478,424] bt_mesh_friend.buf_send_end: err 0
[00:02:29.478,454] bt_mesh_friend.buf_send_end: Waiting 30000 ms for next poll
[00:02:29.811,401] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:29.811,431] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:29.811,431] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 1 frnd->fsn 1
[00:02:29.811,462] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:02:29.811,462] bt_mesh_friend.bt_mesh_friend_poll: Re-sending last PDU
[00:02:29.962,493] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x2000839c
[00:02:29.962,493] bt_mesh_friend.friend_timeout: Sending frnd->last 0x2000839c
[00:02:29.964,233] bt_mesh_friend.buf_send_start: err 0
[00:02:30.024,932] bt_mesh_friend.buf_send_end: err 0
[00:02:30.024,932] bt_mesh_friend.buf_send_end: Waiting 30000 ms for next poll
[00:02:30.357,635] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:30.357,666] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:30.357,666] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 1 frnd->fsn 1
[00:02:30.357,696] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:02:30.357,696] bt_mesh_friend.bt_mesh_friend_poll: Re-sending last PDU
[00:02:30.508,728] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x2000839c
[00:02:30.508,758] bt_mesh_friend.friend_timeout: Sending frnd->last 0x2000839c
[00:02:30.510,620] bt_mesh_friend.buf_send_start: err 0
[00:02:30.571,350] bt_mesh_friend.buf_send_end: err 0
[00:02:30.571,380] bt_mesh_friend.buf_send_end: Waiting 30000 ms for next poll
[00:02:30.903,778] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:30.903,778] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:30.903,808] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 1 frnd->fsn 1
[00:02:30.903,808] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:02:30.903,839] bt_mesh_friend.bt_mesh_friend_poll: Re-sending last PDU
[00:02:31.054,870] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x2000839c
[00:02:31.054,901] bt_mesh_friend.friend_timeout: Sending frnd->last 0x2000839c
[00:02:31.056,610] bt_mesh_friend.buf_send_start: err 0
[00:02:31.117,492] bt_mesh_friend.buf_send_end: err 0
[00:02:31.117,523] bt_mesh_friend.buf_send_end: Waiting 30000 ms for next poll
[00:02:31.450,897] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:31.450,897] bt_mesh_friend.bt_mesh_friend_clear: LPN addr 0x0008 counter 0x0001
[00:02:31.450,897] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:31.450,927] bt_mesh_friend.bt_mesh_friend_match: LPN 0x0008 matched address 0x0008
[00:02:31.450,958] bt_mesh_friend.bt_mesh_friend_enqueue_tx: net_idx 0x0000 dst 0x0008 src 0x000c
[00:02:31.450,958] bt_mesh_friend.friend_lpn_enqueue_tx: LPN 0x0008
[00:02:31.450,988] bt_mesh_friend.enqueue_friend_pdu: type 0
[00:02:31.450,988] bt_mesh_friend.friend_lpn_enqueue_tx: Queued message for LPN 0x0008
[00:02:31.450,988] bt_mesh_friend.friend_clear: LPN 0x0008
[00:02:32.672,790] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:32.672,821] bt_mesh_friend.bt_mesh_friend_clear: LPN addr 0x0008 counter 0x0001
[00:02:32.672,821] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:32.672,821] bt_mesh_friend: No matching LPN addr 0x0008
[00:02:33.893,371] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:33.893,402] bt_mesh_friend.bt_mesh_friend_clear: LPN addr 0x0008 counter 0x0001
[00:02:33.893,402] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:33.893,402] bt_mesh_friend: No matching LPN addr 0x0008
[00:02:43.114,471] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0xfffd
[00:02:43.114,501] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:43.116,821] bt_mesh_friend.bt_mesh_friend_req: LPN 0x0008 rssi -35 recv_delay 100 poll_to 30000ms
[00:02:43.116,821] bt_mesh_friend.offer_delay: ReceiveWindowFactor 10 ReceiveWindow 255 RSSIFactor 10 RSSI -35
[00:02:43.116,851] bt_mesh_friend.offer_delay: Local Delay calculated as 290 ms
[00:02:43.116,851] bt_mesh_friend.enqueue_offer:
[00:02:43.116,851] bt_mesh_friend.encode_friend_ctl: LPN 0x0008
[00:02:43.406,921] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x200083b4
[00:02:43.406,921] bt_mesh_friend.friend_timeout: Sending frnd->last 0x200083b4
[00:02:43.408,660] bt_mesh_friend.buf_send_start: err 0
[00:02:43.417,480] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:43.417,510] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:43.417,510] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 0 frnd->fsn 0
[00:02:43.417,541] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:02:43.417,541] bt_mesh_friend.bt_mesh_friend_poll: Friendship established with 0x0008
[00:02:43.417,541] bt_mesh_friend.encode_update: lpn 0x0008 md 0x00
[00:02:43.417,541] bt_mesh_friend.encode_friend_ctl: LPN 0x0008
[00:02:43.417,572] bt_mesh_friend.bt_mesh_friend_poll: Enqueued Friend Update to empty queue
[00:02:43.469,543] bt_mesh_friend.buf_send_end: err 0
[00:02:43.469,543] bt_mesh_friend: Another request before previous completed sending
[00:02:43.568,572] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 0 last (nil)
[00:02:43.568,572] bt_mesh_friend: Friendship not established with 0x0008
[00:02:43.568,572] bt_mesh_friend.friend_clear: LPN 0x0008
[00:02:43.865,661] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:43.865,692] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:43.865,692] bt_mesh_friend: No matching LPN addr 0x0008
[00:02:44.311,767] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:44.311,798] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:44.311,798] bt_mesh_friend: No matching LPN addr 0x0008
[00:02:44.757,904] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:44.757,904] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:44.757,934] bt_mesh_friend: No matching LPN addr 0x0008
[00:02:45.203,979] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:45.204,010] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:45.204,010] bt_mesh_friend: No matching LPN addr 0x0008
[00:02:45.650,421] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:45.650,421] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:45.650,421] bt_mesh_friend: No matching LPN addr 0x0008
[00:02:54.097,442] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0xfffd
[00:02:54.097,473] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:54.099,853] bt_mesh_friend.bt_mesh_friend_req: LPN 0x0008 rssi -34 recv_delay 100 poll_to 30000ms
[00:02:54.099,884] bt_mesh_friend.offer_delay: ReceiveWindowFactor 10 ReceiveWindow 255 RSSIFactor 10 RSSI -34
[00:02:54.099,884] bt_mesh_friend.offer_delay: Local Delay calculated as 289 ms
[00:02:54.099,914] bt_mesh_friend.enqueue_offer:
[00:02:54.099,914] bt_mesh_friend.encode_friend_ctl: LPN 0x0008
[00:02:54.388,946] bt_mesh_friend.friend_timeout: lpn 0x0008 send_last 1 last 0x200083cc
[00:02:54.388,946] bt_mesh_friend.friend_timeout: Sending frnd->last 0x200083cc
[00:02:54.390,686] bt_mesh_friend.buf_send_start: err 0
[00:02:54.399,627] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:54.399,627] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:54.399,627] bt_mesh_friend.bt_mesh_friend_poll: msg->fsn 0 frnd->fsn 0
[00:02:54.399,658] bt_mesh_friend.friend_recv_delay: Waiting RecvDelay of 151 ms
[00:02:54.399,658] bt_mesh_friend.bt_mesh_friend_poll: Friendship established with 0x0008
[00:02:54.399,658] bt_mesh_friend.encode_update: lpn 0x0008 md 0x00
[00:02:54.399,658] bt_mesh_friend.encode_friend_ctl: LPN 0x0008
[00:02:54.399,688] bt_mesh_friend.bt_m+-----------------------------+d Update to empty queue
[00:02:54.451,538] bt_mesh_friend.buf_| |
[00:02:54.451,568] bt_mesh_friend: Ano| Cannot open /dev/ttyACM1! |mpleted sending
[00:02:54.550,720] bt_mesh_friend.frie| |t 0 last (nil)
[00:02:54.550,720] bt_mesh_friend: Fri+-----------------------------+0008
[00:02:54.550,720] bt_mesh_friend.friend_clear: LPN 0x0008
[00:02:54.846,160] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:54.846,191] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:54.846,191] bt_mesh_friend: No matching LPN addr 0x0008
[00:02:55.291,900] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:55.291,931] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:55.291,931] bt_mesh_friend: No matching LPN addr 0x0008
[00:02:55.738,403] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:55.738,433] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:55.738,433] bt_mesh_friend: No matching LPN addr 0x0008
[00:02:56.184,509] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:56.184,539] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:56.184,570] bt_mesh_friend: No matching LPN addr 0x0008
[00:02:56.629,913] bt_mesh_friend.bt_mesh_friend_match: No matching LPN for address 0x000c
[00:02:56.629,943] bt_mesh_friend.bt_mesh_friend_find: net_idx 0x0000 lpn_addr 0x0008
[00:02:56.629,943] bt_mesh_friend: No matching LPN addr 0x0008

After both devices reboot, they are able to establish the friendship. But same problem would repeat if I press the Friend's button again.

Expected behavior
I expect the LPN to be able to receive messages from Friend. Well, at least it suprises me that the friendship breaks.

Impact
I need the Friend-LPN feature for a project, so it blocks me a bit.

Environment (please complete the following information):

  • Linux Ubuntu 20.04.1 LTS
  • Toolchain : Zephyr SDK
  • Version 2.5.0 rc2 as per version file. The command git rev-parse HEAD gives me : 92c93b1b7fbae1b7623c6423b203d2504c0157aa (which is the latest commit on master at 5th February).

Note : I'm on latest commit on master because before I was at version 2.4.99 (with commit 52ad9a468c1a3ae9a00d1e5aac389c5bfcf087ec) and the friendship couldn't even be set up. Then, as I saw commit changes about friendship, I tried commit c262239680507049a5a8d3c3cb9e18405413cdb3 but I had the same problem as described above. Then I tried most recent commit.
@4ayo 4ayo added the bug The issue is a bug, or the PR is fixing a bug label Feb 5, 2021
@trond-snekvik trond-snekvik mentioned this issue Feb 8, 2021
Merged
@trond-snekvik
Copy link
Contributor

trond-snekvik commented Feb 8, 2021 •
edited
Loading

Hi, thanks for reporting, this uncovered a couple of regressions.

The main issue here comes from the re-encryption mechanism in the friend module, that decrypts and re-encrypts unsegmented messages from the friend node to the LPN. This mechanism has seen two regressions:

  1. The app_idx and net_idx in the message context structure passed to the app_key module is not initialized before being used, leading to invalid appkey index input parameters (see the line [00:09:28.808,532] bt_mesh_app_keys: Unknown AppKey 0x002 in the first friend log).
  2. The sequence number passed to the re-encrypt function is no longer being reset to match the current sequence number, making subsequent messages from the friend to the lpn hit the LPNs message cache.

I have opened #32080 to resolve the issue you're seeing. If you can, please verify that this PR fixes your issue.

@4ayo
Copy link
Author

4ayo commented Feb 8, 2021

Hi,

thanks very much for the PR. At first glance, it seems to solve the issue ! :)

Have a nice day.

@4ayo 4ayo closed this as completed Feb 8, 2021
@trond-snekvik
Copy link
Contributor

Reopening until PR goes in

@trond-snekvik trond-snekvik reopened this Feb 8, 2021
trond-snekvik added a commit to trond-snekvik/zephyr that referenced this issue Mar 9, 2021
@trond-snekvik
Bluetooth: Mesh: Friendship BabbleSim tests
4869392 
Adds Friendship tests to the Bluetooth Mesh BabbleSim test suite. The
friendship tests cover all basic friend establishment and message
sending scenarios, including coverage for previous regressions, such
as zephyrproject-rtos#29544, zephyrproject-rtos#32033 and zephyrproject-rtos#30657.

Signed-off-by: Trond Einar Snekvik <[email protected]>
trond-snekvik added a commit to trond-snekvik/zephyr that referenced this issue Mar 15, 2021
@trond-snekvik
Bluetooth: Mesh: Friendship BabbleSim tests
6bd5705 
Adds Friendship tests to the Bluetooth Mesh BabbleSim test suite. The
friendship tests cover all basic friend establishment and message
sending scenarios, including coverage for previous regressions, such
as zephyrproject-rtos#29544, zephyrproject-rtos#32033 and zephyrproject-rtos#30657.

Signed-off-by: Trond Einar Snekvik <[email protected]>
@trond-snekvik trond-snekvik mentioned this issue Mar 15, 2021
Merged
jhedberg pushed a commit that referenced this issue Mar 19, 2021
@trond-snekvik @jhedberg
Bluetooth: Mesh: Friendship BabbleSim tests
40a2aed 
Adds Friendship tests to the Bluetooth Mesh BabbleSim test suite. The
friendship tests cover all basic friend establishment and message
sending scenarios, including coverage for previous regressions, such
as #29544, #32033 and #30657.

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
Assignees

@jhedberg jhedberg

@trond-snekvik trond-snekvik

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
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Bluetooth: Mesh: Friend re-encrypt regressions trond-snekvik/zephyr
4 participants
@jhedberg @trond-snekvik @carlescufi @4ayo