log buffer overflow on nrf52832

[oni303]

I get a buffer overflow when I try to run the rubble-demo on a nrf52832.

panicked at 'log buffer overflow: failed to grant 4 Bytes (0 available)', rubble-demo/src/logger.rs:70:21
I tried to add --features="log" and --features="rubble/log" during build, did not make any difference.

To "port" the demo form nrf528100 to the nrf52832 I simply replaced nrf528100 with nrf52832.

Any ideas?

[jonas-schievink]

This does happen spuriously sometimes when there's a lot of devices around (which we should definitely fix), do you get no serial output at all before this happens?

[oni303]

Well lost of devices are definitely around.
There are sometimes some lines printed. Here are all the outputs of gdb, openocd and serial:

GDB:

Continuing.

Program	received signal	SIGTRAP, Trace/breakpoint trap.
0x00003f16 in __bkpt ()	at rubble/src/link/comp_id.rs:1968

openocd:

xPSR: 0x01000000 pc: 0x0000d440 msp: 0x20008000, semihosting

<< INIT >>

panicked at 'log buffer overflow: failed to grant 18 Bytes (0 available)', rubble-demo/src/logger.rs:70:21

serial:

--- INIT ---
INFO - Logger ready
3.744ms - TRACE - new LinkLayer, dev=91:c0:25:41:4b:b3(Random)
4.060ms - DEBUG - start_advertise: adv_data = [CompleteLocalName("CONCVRRENS CERTA CELERIS")]
4.409ms - DEBUG - start_advertise: PDU = (Header { PDU Type: AdvInd, TxAdd: true, RxAdd: false, len: 35 }, [91, c0, 25, 41, 4b, b3, 02, 01, 06, 19, 09, 43, 4f, 4e, 43, 56, 52, 52, 45, 4e, 53, 20, 43, 45, 52, 54, 41, 20, 43, 45, 4c, 45, 52, 49, 53])
5.871ms - TRACE - ADV<- Header { PDU Type: AdvNonconnInd, TxAdd: true, RxAdd: false, len: 37 }, [4f, 1b, c5, db, 54, 38, 1e, ff, 06, 00, 01, 09, 20, 02, b8, e5, 50, d7, c8, 63, 83, f8, fe, f4, d2, 83, f6, 86, ae, 35, 9b, 47, 17, 6c, 85, 0a, e4]
212.097ms - Ok(NonconnectableUndirected { advertiser_addr: 4f:1b:c5:db:54:38(Random), advertising_data: [Unknown { ty: 255, data: [6, 0, 1, 9, 32, 2, 184, 229, 80, 215, 200, 99, 131, 248, 254, 244, 210, 131, 246, 134, 174, 53, 155, 71, 23, 108, 133, 10, 228] }] })
213.342ms - 
213.400ms - TRACE - ADV<- Header { PDU Type: AdvInd, TxAdd: true, RxAdd: false, len: 20 }, [ea, 53, 5f, d0, 04, 75, 02, 01, 1a, 0a, ff, 4c, 00, 10, 05, 01, 1c, 1e, ed, 4b]
240.029ms - Ok(ConnectableUndirected { advertiser_addr: ea:53:5f:d0:04:75(Random), advertising_data: [Flags(LE_GENERAL_DISCOVERABLE | SIMUL_LE_BR_CONTROLLER | SIMUL_LE_BR_HOST), Unknown { ty: 255, data: [76, 0, 16, 5, 1, 28, 30, 237, 75] }] })
240.889ms - 
240.948ms - TRACE - ADV<- Header { PDU Type: AdvInd, TxAdd: true, RxAdd: false, len: 20 }, [f``` 

[jonas-schievink]

Yeah then the buffer just gets too full due to the many devices. I meant to fix this yesterday but didn't get to it, so if you want to fix this please go ahead.

The panic happens here:

rubble/demos/demo-utils/src/logging.rs

Lines 66 to 70 in ec7377e

	panic!(
	"log buffer overflow: failed to grant {} Bytes ({} available)",
	bytes.len(),
	max_len
	);

When the queue runs out of space we should instead set a flag on the BbqLogger and drop the rest of the message. Then we need to make sure to print an ellipsis (…) as the next character by checking and resetting the flag at the beginning of write_str.

[oni303]

At the moment I am still learning a lot every time I read/write rust code. So my fixing might take a while.

[jonas-schievink]

No problem, take your time! Let me know if you have any questions.

[thalesfragoso]

Can we close this ?

[jonas-schievink]

Yep, should be fixed!