Mesh Chat Model - Error Message = No free slots for new incoming segmented messages

[BlueMeshUK]

We are getting this message on our RELAY - via PuTTY.

"No free slots for new incoming segmented messages"

uart:~$ [01:00:53.683,380] <wrn> bt_mesh_transport: trans_seg: No free slots for new incoming segmented messages

then >>>

ASSERTION FAIL @ WEST_TOPDIR/zephyr/lib/os/ring_buffer.c:73

We are getting this error - using CHAT MODEL in MESH.  The RELAY gives us this same error message - we have increased the CONFIG_BT_MESH_ADV_BUF_COUNT value from 13 to 50.

We read here >>>  "No free slots" error while sending message  that adding a timing delay may help. 

We have not added a timing delay yet but lets say we use 0.1s between receiving and transmitting on to the proxy or the next Relay. Is this because of timing issues between the next available Tx slot being ready and the device being ready - or mistiming i should say.

How do we add a small delay?

We put this into our VS Code build - yes?

Please help if you can give us some information - many thanks.

We have nRF52840 BLE > nRF21540 DK as RELAY > nRF21540 DK as proxy.  

Thanks - Richard 

[AHaug]

Hi,

Based on my understanding of the case it looks like you might be changing the wrong parameter. https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/kconfig/index.html#CONFIG_BT_MESH_ADV_BUF_COUNT states "Number of advertising buffers available for sending local messages. This should be chosen based on the number of local messages that the node can send simultaneously.", while afaik you have issues with relaying messages, so I believe that increasing  https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/kconfig/index.html#CONFIG_BT_MESH_RELAY_BUF_COUNT should resolve your issue

Could you attempt to increase this configuration and to post the complete device log if this does not resolve the issue?

Kind regards,
Andreas

[BlueMeshUK]

Hi Andreas, I'm working with Richard.

I've added 

CONFIG_BT_MESH_RELAY_BUF_COUNT=256 into the prj.conf file and the messages No free slots" error while sending message have disappeared.

i also added to the KConfig file the lines below (please let me know if it is completely redundant)

config BT_MESH_RELAY_BUF_COUNT

int "Number of advertising buffers for relayed messages"

default 32

range 1 256

help

Number of advertising buffers available for messages to be relayed.

High number of advertising buffers increases the reliability of the

mesh network. Low number of advertising buffers reduces the message

latency on the Relay Node, but at the same time increases the amount

of packet drops. When considering the message latency, also consider

the values of BT_MESH_RELAY_RETRANSMIT_COUNT and

BT_MESH_RELAY_RETRANSMIT_INTERVAL. A higher number of

BT_MESH_RELAY_ADV_SETS allows the increase in the number of buffers

while maintaining the latency.

[TimD]

Hi Andreas,

Ok so we've set the message size to 9bytes. This is a section of the log from the relay

<0x004C>: 030134
<0x004E>: 030336
<0x004A>: 030035
<0x004F>: 030735
message echo: Re:0000
<0x0050>: 030935
<0x004B>: 030535
<0x004D>: 030235
<0x004C>: 030134
<0x004E>: 030336
<0x004A>: 030035
<0x004F>: 030735
<0x0050>: 030935
<0x004B>: 030535
<0x004C>: 030134
<0x004E>: 030336
<0x004F>: 030735
<0x0050>: 030935
<0x004A>: 030035
<0x004C>: 030134
<0x004E>: 030336
<0x004F>: 030735
<0x0050>: 030935

i.e all warning message have disappeared. 

Somewhere in your documentation its says: For a vendor specific model, such as the chat model, messages with 9 or less bytes of payload should get sent in one packet (i.e. not segmented), which would go significantly faster due to two properties of segmented messages:

 

[BlueMeshUK]

Andreas - this would make life a LOT easier if 9 bytes was the default setting - i think it is set to Max 60 bytes by default - anyone reading this - start at 9 bytes and work up from there - dont start at the Nordic default or you may repeat our problems. 

[TimD]

Hi Andreas, unfortunately just been running another test with 9 byte messages and the relay and proxy crashed with the error ASSERTION FAIL @ WEST_TOPDIR/zephyr/lib/os/ring_buffer.c:73.

There is nothing in the log files that help.

[BlueMeshUK]

Hi Andreas - we have a commercial requirement to get this Sprint fixed - so it would be very helpful to help solve this issue with us ... FYI ... we moved from Wirepas to Bluetooth Mesh after some discussions with Nordic and we really need to get this sorted out now - if you need us to pay you a fee to solve the issue can you please send me a meeting link to richard:bluemeshsolutions.com so we can discuss together.  Thanks Richard 

[AHaug]

Hi, 

TimD said:

WEST_TOPDIR/zephyr/lib/os/ring_buffer.c:73.

There is nothing in the log files that help.

Could you post the contents of the log nonetheless? Could you also post a full device log?

TimD said:

Sorry I've just checked and the messages No free slots" error while sending message  are still appearing.

In the previous case you had a ring buffer error it stated that the ring buffer was full and that you needed to drain the buffer. Did you also ensure that the buffer was emptied or did you only increase the buffer size?

BlueMeshUK said:

discussions with Nordic and we really need to get this sorted out now - if you need us to pay you a fee to solve the issue can you please send me a meeting link to richard:bluemeshsolutions.com so we can discuss together.  Thanks Richard 

I would recommend that you stay in contact with your regional sales director regarding mapping your needs so they can look into them. Let me know if you need their contact information and I'll send it to you in a PM. 

Kind regards,
Andreas

[BlueMeshUK]

I have reached out to Claire Steed in the UK - is that the correct person?

Andreas in your answer above you mention ensuring empty the buffer - but you dont explain how to do this - can you be clear in your reply - what is the parameter or commend to drain the buffer please - it would make your reply much more useful to us if you recommend and then explain or demonstrate - thanks - Richard 

[AHaug]

BlueMeshUK said:

I have reached out to Claire Steed in the UK - is that the correct person?

Yes, Claire is the correct person to reach out to for UK

BlueMeshUK said:

Andreas in your answer above you mention ensuring empty the buffer - but you dont explain how to do this - can you be clear in your reply - what is the parameter or commend to drain the buffer please - it would make your reply much more useful to us if you recommend and then explain or demonstrate - thanks - Richard 

Of course, I will write you a more thorough summary with some more items before I leave the office for the day

I will get back to you within a few hours

Kind regards,
Andreas 

[BlueMeshUK]

Thanks Andreas.

We are wondering if we can use the he ring_buf_reset() command in Zephyr - set it to zero every x counts of a write and then reset to clear it all up - its a bit of a Hack of course - but if it works.  

We also see there is a ring buffer command to show how much space remains in the Buffer >>>  ring_buf_space_get() - if we get that value and its nearing the Ring Buffer size declared on >>> ring_buf_init - then we can print the value of how full or nearly full the ring buffer is - then if its over 1000 of 1024 max - or even at max - we can then reset the ring buffer and clear it out - to 0 - and we go again.

It takes a couple of hours to fill the buffer because we are only sending small 9 byte messages - and we have a theoretical 200 9 byte messages every minute.  In test we have 17 beacons sending messages every 5s - as a test - so thats 17 x 12 per minute = 204 per minute.  

We look forward to your help - we have a meeting to set up the field trial on Wed with a UK customer so we need to either solve or hack/solve the issues so we can move into field trial.  Thanks - Richard and Tim 

[AHaug]

Hi again,

AHaug said:

WEST_TOPDIR/zephyr/lib/os/ring_buffer.c:73.

There is nothing in the log files that help.

I believe we have been lead on by the info log from your previous ring_buffer error stating "cdc_acm_poll_out: Ring buffer full, drain buffer". After looking through https://github.com/nrfconnect/sdk-zephyr/blob/e4511cfcb7a672ca1bb0d6296dc257df6af0b12f/subsys/usb/device/class/cdc_acm.c#L1000C1-L1026C1 it is now clear that it is not something that the user needs to do, but instead that it is automatically handled by the module (i.e the log should probably be changed to "draining buffer" instead of the imperative "drain buffer")

After you see the info message saying "Ring buffer full, drain buffer", are you able to verify if the buffer actually has been drained?

BlueMeshUK said:

Andreas - this would make life a LOT easier if 9 bytes was the default setting - i think it is set to Max 60 bytes by default - anyone reading this - start at 9 bytes and work up from there - dont start at the Nordic default or you may repeat our problems. 

9 bytes + 3 bytes for vendor specific opcode = 12 bytes = maximum for a pack. This means that custom messages that are longer than 9 bytes leads to a SAR which leads to overhead (acking on the network- or transport level). 

Regarding the segmented message isse:

I see that you've posted a reply in  "No free slots" error while sending message without an answer (the engineer holding that case has been out of office). In that case the issue was resolved by adding a small delay to the transmission. Have you tried this in your project? 

Finally could you try to increase https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/kconfig/index.html#CONFIG_BT_MESH_RX_SEG_MSG_COUNT and/or https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/kconfig/index.html#CONFIG_BT_MESH_SEG_BUFS to see if this resolves the segmented messages issue?

Kind regards,
Andreas

[TimD]

Hi Andreas,

I ran a test with 2 proxy's.  Proxy2 crashed at 01:16:46. The log of the Proxy1 finally captured a message (but didn't crash). Any idea what this is?

01:16:47: 030034 => ['id':'0300', 'voltage':'3.4'] message_no:788
b'[13:26:08.312,713] \x1b[0m<inf> usb_device: usb_halt_endpoint_req: Clear halt ep 0x82\x1b[0m\r\n'
b'[13:26:08.343,200] \x1b[0m<inf> usb_device: usb_halt_endpoint_req: Clear halt ep 0x82\x1b[0m\r\n'
b'\x1b[10D\x1b[J[13:26:08.312,713] \x1b[0m<inf> usb_device: usb_halt_endpoint_req: Clear halt ep 0x82\x1b[0m\r\n'
b'\x1b[1;32muart:~$ \x1b[m^[\x1b[10D\x1b[J[13:26:08.343,200] \x1b[0m<inf> usb_device: usb_halt_endpoint_req: Clear halt ep 0x82\x1b[0m\r\n'
b'\x1b[1;32muart:~$ \x1b[m^[\x1b[10D\x1b[J\x1b[1;32muart:~$ \x1b[m^[<0x0058>: 030531\r\n'
01:16:47: 030531 => ['id':'0305', 'voltage':'3.1'] message_no:789