espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
12.56k stars 7.02k forks source link

Guru Meditation Error and rebooting when using ESP32 bluetooth (IDFGH-12672) #13664

Open Zakary-D opened 3 weeks ago

Zakary-D commented 3 weeks ago

Answers checklist.

IDF version.

v5.1.3-416-gd23b7a0361

Espressif SoC revision.

ESP32D0WDQ5(revision 3)

Operating System used.

Linux

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

None

Development Kit.

ESP-WROVER-KIT

Power Supply used.

USB

What is the expected behavior?

send modified AVDTP packet to peer.

What is the actual behavior?

memory corruption and rebooting

Steps to reproduce.

1.modify code: esp-idf/components/bt/host/bluedroid/stack/avdt/avdt_ad.c

UINT8 avdt_ad_write_req(UINT8 type, tAVDT_CCB *p_ccb, tAVDT_SCB *p_scb, BT_HDR *p_buf)
{
    UINT8   tcid;

    /* get tcid from type, scb */
    tcid = avdt_ad_type_to_tcid(type, p_scb);

    srand(time(NULL));
    // p_buf[0].event = (uint16_t)rand();

    if(type == AVDT_CHAN_MEDIA){
        p_buf->event = (uint16_t)rand();
        p_buf->len = (uint16_t)rand() % 255;
        p_buf->offset = (uint16_t)rand();
        p_buf->layer_specific = (uint16_t)rand();
        for(int i = 0; i < p_buf->len; ++i) p_buf->data[i] = (uint16_t)rand();
    }

    static int dk_cnt = 0;
    if(++dk_cnt % 1000 == 0){
        dk_cnt = 0, printf("\n\n avdt_ad_write_req \n");    
        printf("%" PRIu16 " ", p_buf->event);
        printf("%" PRIu16 " ", p_buf->len);
        printf("%" PRIu16 " ", p_buf->offset);
        printf("%" PRIu16 " \n", p_buf->layer_specific);
        for(int i = 0; i < p_buf->len; ++i) printf("%" PRIu16 " ", p_buf->data[i]);
        printf("\n\n");
    }

    return L2CA_DataWrite(avdt_cb.ad.rt_tbl[avdt_ccb_to_idx(p_ccb)][tcid].lcid, p_buf);
}
  1. change the target device name of example/a2dp_source to my headphone: HUAWEI FreeBuds 4i
  2. use idf.py to build example/a2dp_source

4.flash it to ESP-WROVER-KIT and monitor it 5.about half an hour later, something get wrong and the development board rebooting

Debug Logs.

Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x40093232  PS      : 0x00060333  A0      : 0x80092e87  A1      : 0x3ffd0350  
0x40093232: remove_free_block at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:332
(inlined by) block_remove at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:380
(inlined by) block_merge_next at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:486
(inlined by) tlsf_free at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:1123

A2      : 0x3ffcc144  A3      : 0x3ffd7838  A4      : 0x3ffd7830  A5      : 0x3ffc0042  
A6      : 0x00000028  A7      : 0x00000058  A8      : 0x00000018  A9      : 0x3ffd8844  
A10     : 0x3ffd8844  A11     : 0x00000000  A12     : 0x0099009d  A13     : 0x00000004  
A14     : 0xb33fffff  A15     : 0xb33fffff  SAR     : 0x0000001c  EXCCAUSE: 0x0000001d  
EXCVADDR: 0x009900a9  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  
0x4000c2e0: memcpy in ROM
0x4000c2f6: memcpy in ROM

Backtrace: 0x4009322f:0x3ffd0350 0x40092e84:0x3ffd0370 0x40082362:0x3ffd0390 0x4009406d:0x3ffd03b0 0x400de242:0x3ffd03d0 0x400df122:0x3ffd03f0 0x400de459:0x3ffd0410 0x4010c2fa:0x3ffd0430 0x400de4b5:0x3ffd0450 0x4010d2ce:0x3ffd0470 0x4010d19a:0x3ffd0490 0x40090ad5:0x3ffd04c0
0x4009322f: remove_free_block at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:331
(inlined by) block_remove at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:380
(inlined by) block_merge_next at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:486
(inlined by) tlsf_free at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:1123
0x40092e84: multi_heap_free_impl at /root/esp/esp-idf/components/heap/multi_heap.c:231
0x40082362: heap_caps_free at /root/esp/esp-idf/components/heap/heap_caps.c:388
0x4009406d: free at /root/esp/esp-idf/components/newlib/heap.c:39
0x400de242: transmit_fragment at /root/esp/esp-idf/components/bt/host/bluedroid/hci/hci_layer.c:350
0x400df122: fragment_and_dispatch at /root/esp/esp-idf/components/bt/host/bluedroid/hci/packet_fragmenter.c:132
0x400de459: event_packet_ready at /root/esp/esp-idf/components/bt/host/bluedroid/hci/hci_layer.c:338
0x4010c2fa: fixed_queue_process at /root/esp/esp-idf/components/bt/common/osi/fixed_queue.c:254
0x400de4b5: hci_downstream_data_handler at /root/esp/esp-idf/components/bt/host/bluedroid/hci/hci_layer.c:238
0x4010d2ce: osi_thread_generic_event_handler at /root/esp/esp-idf/components/bt/common/osi/thread.c:425
0x4010d19a: osi_thread_run at /root/esp/esp-idf/components/bt/common/osi/thread.c:165 (discriminator 1)
0x40090ad5: vPortTaskWrapper at /root/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

ELF file SHA256: fb53a7e2e55ccb03

Rebooting...
ets Jul 29 2019 12:21:46

More Information.

No response

Dazza0 commented 3 weeks ago

@Zakary-D

Looks like it's crashing tlsf.c:remove_free_block on these lines when accessing address EXCVADDR: 0x009900a9

    next->prev_free = prev;
    prev->next_free = next;

It might be due to heap corruption (where the heap block headers are overwritten). Could you enable GDB stub on panic (see CONFIG_ESP_SYSTEM_PANIC_GDBSTUB), and when the crash occurs, print out the current values block_header_t* block.

Zakary-D commented 3 weeks ago

@Zakary-D

Looks like it's crashing tlsf.c:remove_free_block on these lines when accessing address EXCVADDR: 0x009900a9

  next->prev_free = prev;
  prev->next_free = next;

It might be due to heap corruption (where the heap block headers are overwritten). Could you enable GDB stub on panic (see CONFIG_ESP_SYSTEM_PANIC_GDBSTUB), and when the crash occurs, print out the current values block_header_t* block.

I tried running it again but maybe due to rand(), a new crash was triggered, I think the cause might be the same. And I have never used gdb stub. Can you teach me how to print the value of block? Thank you.

I (471377) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (481377) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (481377) BT_AV: a2dp media stopping...

***ERROR*** A stack overflow in task BtAppTask has been detected.

Backtrace: 0x40081a6a:0x3ffd58a0 0x4008e2a9:0x3ffd58c0 0x40090f7e:0x3ffd58e0 0x4008fb07:0x3ffd5960 0x4009110c:0x3ffd5980 0x400910be:0x3ffd63a0 0x3ffd6819:0xb33fffff |<-CORRUPTED
0x40081a6a: panic_abort at /root/esp/esp-idf/components/esp_system/panic.c:466
0x4008e2a9: esp_system_abort at /root/esp/esp-idf/components/esp_system/port/esp_system_chip.c:84
0x40090f7e: vApplicationStackOverflowHook at /root/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:581
0x4008fb07: vTaskSwitchContext at /root/esp/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:3840
0x4009110c: _frxt_dispatch at /root/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/portasm.S:450
0x400910be: _frxt_int_exit at /root/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/portasm.S:245

ELF file SHA256: be519cf231a6f919

Entering gdb stub now.
$T0b#e6GNU gdb (esp-gdb) 12.1_20231023
Copyright (C) 2022 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "--host=x86_64-linux-gnu --target=xtensa-esp-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /root/esp/a2dp_source/build/a2dp_source.elf...
Remote debugging using /dev/ttyUSB1
warning: multi-threaded target stopped without sending a thread-id, using first non-exited thread
[Switching to Thread 1]
0x40081a6d in panic_abort (
    details=0x3ffd58ec "***ERROR*** A stack overflow in task BtAppTask has been detected.")
    at /root/esp/esp-idf/components/esp_system/panic.c:466
466     *((volatile int *) 0) = 0; // NOLINT(clang-analyzer-core.NullDereference) should be an invalid operation on targets
shangke1112 commented 3 weeks ago

I think it may be using some memory that has already been released and then repeatedly releasing the same address; p_buf->event = (uint16_t)rand(); p_buf->len = (uint16_t)rand() % 255; p_buf->offset = (uint16_t)rand(); p_buf->layer_specific = (uint16_t)rand(); These value have the certain meaning, and I am not sure what would happen if given a random value.

Zakary-D commented 3 weeks ago

I think it may be using some memory that has already been released and then repeatedly releasing the same address; p_buf->event = (uint16_t)rand(); p_buf->len = (uint16_t)rand() % 255; p_buf->offset = (uint16_t)rand(); p_buf->layer_specific = (uint16_t)rand(); These value have the certain meaning, and I am not sure what would happen if given a random value.

I think so. What I am doing is trying to modify the bluetooth stack of esp-idf, change the data of packets and fuzz bluetooth device.

Zakary-D commented 2 weeks ago

@Zakary-D

Looks like it's crashing tlsf.c:remove_free_block on these lines when accessing address EXCVADDR: 0x009900a9

  next->prev_free = prev;
  prev->next_free = next;

It might be due to heap corruption (where the heap block headers are overwritten). Could you enable GDB stub on panic (see CONFIG_ESP_SYSTEM_PANIC_GDBSTUB), and when the crash occurs, print out the current values block_header_t* block.

I tried a new mutation method and this bug happenned again, the stack backtrace information printed was same. The new mutation is like this:

UINT8 avdt_ad_write_req(UINT8 type, tAVDT_CCB *p_ccb, tAVDT_SCB *p_scb, BT_HDR *p_buf)
{
    srand(time(NULL));

    UINT8   tcid;

    // type = rand() % AVDT_CHAN_NUM_TYPES;

    /* get tcid from type, scb */
    tcid = avdt_ad_type_to_tcid(type, p_scb);

    // p_buf[0].event = (uint16_t)rand();

    if(type == AVDT_CHAN_MEDIA){
        for(int i = 0; i < p_buf->len; ++i) p_buf->data[i] = (uint16_t)rand();

        p_buf->len = (uint16_t)rand() % 255;
        // printf("\n %d \n", p_buf->len);
        // for(int i = 0; i < p_buf->len; ++i) printf("%d\n", p_buf->data[i]);
        // printf("\n\n");

        p_buf->event = (uint16_t)rand();
        p_buf->offset = (uint16_t)rand();
        p_buf->layer_specific = (uint16_t)rand();
    }

    // static int dk_cnt = 0;
    // if(++dk_cnt % 1000 == 0){
    //     dk_cnt = 0, printf("\n\n avdt_ad_write_req \n");    
    //     printf("%" PRIu16 " ", p_buf->event);
    //     printf("%" PRIu16 " ", p_buf->len);
    //     printf("%" PRIu16 " ", p_buf->offset);
    //     printf("%" PRIu16 " \n", p_buf->layer_specific);
    //     for(int i = 0; i < p_buf->len; ++i) printf("%" PRIu16 " ", p_buf->data[i]);
    //     printf("\n\n");
    // }

    return L2CA_DataWrite(avdt_cb.ad.rt_tbl[avdt_ccb_to_idx(p_ccb)][tcid].lcid, p_buf);
}

and the debug information is :

TTTT  HUAWEI FreeBuds 4i
I (23887) BT_AV: Found a target device, address b8:8e:82:9a:be:50, name HUAWEI FreeBuds 4i
I (23897) BT_AV: Cancel device discovery ...
I (23897) BT_AV: Device discovery stopped.
I (23907) BT_AV: a2dp connecting to peer: HUAWEI FreeBuds 4i
W (23907) BT_APPL: reset flags
I (23917) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0x0
W (24337) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
I (24337) BT_AV: event: 16
E (24737) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (24957) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0x8
I (24957) BT_AV: bt_app_av_state_connecting_hdlr, delay value: 1500 * 1/10 ms
W (25067) BT_APPL: new conn_srvc id:18, app_id:0
I (25067) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0x0
I (25067) BT_AV: a2dp connected
W (25187) BT_APPL: bta_av_proc_meta_cmd unhandled RC vendor PDU: 0x30
I (31357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (31357) BT_AV: a2dp media ready checking ...
I (31357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0x3
I (31357) BT_AV: a2dp media ready, starting ...
W (31367) BT_APPL: new conn_srvc id:18, app_id:1
I (31407) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0x8
I (31407) BT_AV: bt_app_av_state_connected_hdlr, delay value: 1500 * 1/10 ms
I (31407) BT_LOG: bta_av_link_role_ok hndl:x41 role:0 conn_audio:x1 bits:1 features:x864b

I (31417) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0x3
I (31427) BT_AV: a2dp media start successfully.
I (31427) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0x1
W (31497) BT_APPL: bta_av_proc_meta_cmd unhandled RC vendor PDU: 0x30
I (41357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (51357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (61357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (71357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (81357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (91357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (101357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (111357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (121357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (131357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (141357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (151357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (161357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (171357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x400933ac  PS      : 0x00060933  A0      : 0x80092fff  A1      : 0x3ffd0900  
0x400933ac: remove_free_block at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:333
 (inlined by) block_remove at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:380
 (inlined by) block_merge_next at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:486
 (inlined by) tlsf_free at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:1123

A2      : 0x3ffcc6ec  A3      : 0x3ffd7b08  A4      : 0x3ffd7b00  A5      : 0x005f0063  
A6      : 0xa579887f  A7      : 0x7f23217d  A8      : 0x00000009  A9      : 0x3ffd9b28  
A10     : 0x3ffd9b28  A11     : 0x00000009  A12     : 0x2080c6ec  A13     : 0x00000004  
A14     : 0xb33fffff  A15     : 0xb33fffff  SAR     : 0x0000001c  EXCCAUSE: 0x0000001d  
EXCVADDR: 0x005f006b  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  
0x4000c2e0: memcpy in ROM
0x4000c2f6: memcpy in ROM

Backtrace: 0x400933a9:0x3ffd0900 0x40092ffc:0x3ffd0920 0x40082336:0x3ffd0940 0x400941e5:0x3ffd0960 0x400ded9e:0x3ffd0980 0x400dfc7e:0x3ffd09a0 0x400defb5:0x3ffd09c0 0x4010cec6:0x3ffd09e0 0x400df011:0x3ffd0a00 0x4010de9a:0x3ffd0a20 0x4010dd66:0x3ffd0a40 0x40090c4d:0x3ffd0a70
0x400933a9: remove_free_block at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:331
 (inlined by) block_remove at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:380
 (inlined by) block_merge_next at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:486
 (inlined by) tlsf_free at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:1123
0x40092ffc: multi_heap_free_impl at /root/esp/esp-idf/components/heap/multi_heap.c:231
0x40082336: heap_caps_free at /root/esp/esp-idf/components/heap/heap_caps.c:388
0x400941e5: free at /root/esp/esp-idf/components/newlib/heap.c:39
0x400ded9e: transmit_fragment at /root/esp/esp-idf/components/bt/host/bluedroid/hci/hci_layer.c:350
0x400dfc7e: fragment_and_dispatch at /root/esp/esp-idf/components/bt/host/bluedroid/hci/packet_fragmenter.c:132
0x400defb5: event_packet_ready at /root/esp/esp-idf/components/bt/host/bluedroid/hci/hci_layer.c:338
0x4010cec6: fixed_queue_process at /root/esp/esp-idf/components/bt/common/osi/fixed_queue.c:254
0x400df011: hci_downstream_data_handler at /root/esp/esp-idf/components/bt/host/bluedroid/hci/hci_layer.c:238
0x4010de9a: osi_thread_generic_event_handler at /root/esp/esp-idf/components/bt/common/osi/thread.c:425
0x4010dd66: osi_thread_run at /root/esp/esp-idf/components/bt/common/osi/thread.c:165 (discriminator 1)
0x40090c4d: vPortTaskWrapper at /root/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

ELF file SHA256: e8e2749bc7185461

Entering gdb stub now.
$T0b#e6GNU gdb (esp-gdb) 12.1_20231023
Copyright (C) 2022 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "--host=x86_64-linux-gnu --target=xtensa-esp-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /root/esp/a2dp_source/build/a2dp_source.elf...
Remote debugging using /dev/ttyUSB2
warning: multi-threaded target stopped without sending a thread-id, using first non-exited thread
remove_free_block (sl=9, fl=9, block=0x3ffd9b28, control=0x3ffcc6ec) at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:333
333     prev->next_free = next;
(gdb) print block
$1 = (block_header_t *) 0x3ffd9b28
(gdb) 

And I have printed the value of block, which was 0x3ffd9b28.

Zakary-D commented 2 weeks ago

@Zakary-D Looks like it's crashing tlsf.c:remove_free_block on these lines when accessing address EXCVADDR: 0x009900a9

    next->prev_free = prev;
    prev->next_free = next;

It might be due to heap corruption (where the heap block headers are overwritten). Could you enable GDB stub on panic (see CONFIG_ESP_SYSTEM_PANIC_GDBSTUB), and when the crash occurs, print out the current values block_header_t* block.

I tried a new mutation method and this bug happenned again, the stack backtrace information printed was same. The new mutation is like this:

UINT8 avdt_ad_write_req(UINT8 type, tAVDT_CCB *p_ccb, tAVDT_SCB *p_scb, BT_HDR *p_buf)
{
    srand(time(NULL));

    UINT8   tcid;

    // type = rand() % AVDT_CHAN_NUM_TYPES;

    /* get tcid from type, scb */
    tcid = avdt_ad_type_to_tcid(type, p_scb);

    // p_buf[0].event = (uint16_t)rand();

    if(type == AVDT_CHAN_MEDIA){
        for(int i = 0; i < p_buf->len; ++i) p_buf->data[i] = (uint16_t)rand();

        p_buf->len = (uint16_t)rand() % 255;
        // printf("\n %d \n", p_buf->len);
        // for(int i = 0; i < p_buf->len; ++i) printf("%d\n", p_buf->data[i]);
        // printf("\n\n");

        p_buf->event = (uint16_t)rand();
        p_buf->offset = (uint16_t)rand();
        p_buf->layer_specific = (uint16_t)rand();
    }

    // static int dk_cnt = 0;
    // if(++dk_cnt % 1000 == 0){
    //     dk_cnt = 0, printf("\n\n avdt_ad_write_req \n");    
    //     printf("%" PRIu16 " ", p_buf->event);
    //     printf("%" PRIu16 " ", p_buf->len);
    //     printf("%" PRIu16 " ", p_buf->offset);
    //     printf("%" PRIu16 " \n", p_buf->layer_specific);
    //     for(int i = 0; i < p_buf->len; ++i) printf("%" PRIu16 " ", p_buf->data[i]);
    //     printf("\n\n");
    // }

    return L2CA_DataWrite(avdt_cb.ad.rt_tbl[avdt_ccb_to_idx(p_ccb)][tcid].lcid, p_buf);
}

and the debug information is :

TTTT  HUAWEI FreeBuds 4i
I (23887) BT_AV: Found a target device, address b8:8e:82:9a:be:50, name HUAWEI FreeBuds 4i
I (23897) BT_AV: Cancel device discovery ...
I (23897) BT_AV: Device discovery stopped.
I (23907) BT_AV: a2dp connecting to peer: HUAWEI FreeBuds 4i
W (23907) BT_APPL: reset flags
I (23917) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0x0
W (24337) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
I (24337) BT_AV: event: 16
E (24737) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (24957) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0x8
I (24957) BT_AV: bt_app_av_state_connecting_hdlr, delay value: 1500 * 1/10 ms
W (25067) BT_APPL: new conn_srvc id:18, app_id:0
I (25067) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0x0
I (25067) BT_AV: a2dp connected
W (25187) BT_APPL: bta_av_proc_meta_cmd unhandled RC vendor PDU: 0x30
I (31357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (31357) BT_AV: a2dp media ready checking ...
I (31357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0x3
I (31357) BT_AV: a2dp media ready, starting ...
W (31367) BT_APPL: new conn_srvc id:18, app_id:1
I (31407) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0x8
I (31407) BT_AV: bt_app_av_state_connected_hdlr, delay value: 1500 * 1/10 ms
I (31407) BT_LOG: bta_av_link_role_ok hndl:x41 role:0 conn_audio:x1 bits:1 features:x864b

I (31417) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0x3
I (31427) BT_AV: a2dp media start successfully.
I (31427) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0x1
W (31497) BT_APPL: bta_av_proc_meta_cmd unhandled RC vendor PDU: 0x30
I (41357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (51357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (61357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (71357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (81357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (91357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (101357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (111357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (121357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (131357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (141357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (151357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (161357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (171357) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x400933ac  PS      : 0x00060933  A0      : 0x80092fff  A1      : 0x3ffd0900  
0x400933ac: remove_free_block at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:333
 (inlined by) block_remove at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:380
 (inlined by) block_merge_next at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:486
 (inlined by) tlsf_free at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:1123

A2      : 0x3ffcc6ec  A3      : 0x3ffd7b08  A4      : 0x3ffd7b00  A5      : 0x005f0063  
A6      : 0xa579887f  A7      : 0x7f23217d  A8      : 0x00000009  A9      : 0x3ffd9b28  
A10     : 0x3ffd9b28  A11     : 0x00000009  A12     : 0x2080c6ec  A13     : 0x00000004  
A14     : 0xb33fffff  A15     : 0xb33fffff  SAR     : 0x0000001c  EXCCAUSE: 0x0000001d  
EXCVADDR: 0x005f006b  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  
0x4000c2e0: memcpy in ROM
0x4000c2f6: memcpy in ROM

Backtrace: 0x400933a9:0x3ffd0900 0x40092ffc:0x3ffd0920 0x40082336:0x3ffd0940 0x400941e5:0x3ffd0960 0x400ded9e:0x3ffd0980 0x400dfc7e:0x3ffd09a0 0x400defb5:0x3ffd09c0 0x4010cec6:0x3ffd09e0 0x400df011:0x3ffd0a00 0x4010de9a:0x3ffd0a20 0x4010dd66:0x3ffd0a40 0x40090c4d:0x3ffd0a70
0x400933a9: remove_free_block at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:331
 (inlined by) block_remove at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:380
 (inlined by) block_merge_next at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:486
 (inlined by) tlsf_free at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:1123
0x40092ffc: multi_heap_free_impl at /root/esp/esp-idf/components/heap/multi_heap.c:231
0x40082336: heap_caps_free at /root/esp/esp-idf/components/heap/heap_caps.c:388
0x400941e5: free at /root/esp/esp-idf/components/newlib/heap.c:39
0x400ded9e: transmit_fragment at /root/esp/esp-idf/components/bt/host/bluedroid/hci/hci_layer.c:350
0x400dfc7e: fragment_and_dispatch at /root/esp/esp-idf/components/bt/host/bluedroid/hci/packet_fragmenter.c:132
0x400defb5: event_packet_ready at /root/esp/esp-idf/components/bt/host/bluedroid/hci/hci_layer.c:338
0x4010cec6: fixed_queue_process at /root/esp/esp-idf/components/bt/common/osi/fixed_queue.c:254
0x400df011: hci_downstream_data_handler at /root/esp/esp-idf/components/bt/host/bluedroid/hci/hci_layer.c:238
0x4010de9a: osi_thread_generic_event_handler at /root/esp/esp-idf/components/bt/common/osi/thread.c:425
0x4010dd66: osi_thread_run at /root/esp/esp-idf/components/bt/common/osi/thread.c:165 (discriminator 1)
0x40090c4d: vPortTaskWrapper at /root/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

ELF file SHA256: e8e2749bc7185461

Entering gdb stub now.
$T0b#e6GNU gdb (esp-gdb) 12.1_20231023
Copyright (C) 2022 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "--host=x86_64-linux-gnu --target=xtensa-esp-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /root/esp/a2dp_source/build/a2dp_source.elf...
Remote debugging using /dev/ttyUSB2
warning: multi-threaded target stopped without sending a thread-id, using first non-exited thread
remove_free_block (sl=9, fl=9, block=0x3ffd9b28, control=0x3ffcc6ec) at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:333
333       prev->next_free = next;
(gdb) print block
$1 = (block_header_t *) 0x3ffd9b28
(gdb) 

And I have printed the value of block, which was 0x3ffd9b28.

And there are someting else:

(gdb) print block
$1 = (block_header_t *) 0x3ffd9b28
(gdb) info line
Line 333 of "/root/esp/esp-idf/components/heap/tlsf/tlsf.c" starts at address 0x40093234 <tlsf_free+252> and ends at 0x40093236 <tlsf_free+254>.
(gdb) frame
#0  remove_free_block (sl=9, fl=9, block=0x3ffd9b28, control=0x3ffcc6ec) at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:333
333     prev->next_free = next;
(gdb) info locals
prev = 0x5f0063
next = 0x2080c6ec
__func__ = "remove_free_block"
(gdb) print block[0]
$2 = {prev_phys_block = 0x3ffd7b00, size = 25807, next_free = 0x2080c6ec, prev_free = 0x5f0063}
(gdb) print block[1]
$3 = {prev_phys_block = 0xbfef0042, size = 4064213689, next_free = 0x325b4ad0, prev_free = 0xb2db7cd4}
(gdb) print block[2]
$4 = {prev_phys_block = 0x5e790bb5, size = 3410603119, next_free = 0xf6da59a8, prev_free = 0x15c7195f}
(gdb) print block[4]
$5 = {prev_phys_block = 0xb7fe0d2b, size = 3573607566, next_free = 0xa2cc40d6, prev_free = 0xe3ebbd6e}
(gdb) print block[3]
$6 = {prev_phys_block = 0xf88e371e, size = 223028222, next_free = 0xe3f91482, prev_free = 0xae4c3c16}
(gdb) print block[5]
$7 = {prev_phys_block = 0x9d8801aa, size = 4133773694, next_free = 0xc26591d2, prev_free = 0x8824feaf}
(gdb) print block[6]
$8 = {prev_phys_block = 0xc780847c, size = 569304532, next_free = 0xb64a2de, prev_free = 0x23217dde}
(gdb) print block[7]
$9 = {prev_phys_block = 0xa579887f, size = 3995053791, next_free = 0xd4b5e6bd, prev_free = 0x2c156e6e}
(gdb) print block[8]
$10 = {prev_phys_block = 0xa1adcfa8, size = 299015440, next_free = 0x87902630, prev_free = 0x452dc51}
(gdb) print block[9]
$11 = {prev_phys_block = 0xfcec4b78, size = 2263880289, next_free = 0x2d9aa5ef, prev_free = 0x74116d59}
(gdb) print block[10]
$12 = {prev_phys_block = 0x643c31b2, size = 1770536477, next_free = 0xdd23a975, prev_free = 0x5b041935}
(gdb) print block[11]
$13 = {prev_phys_block = 0xfb2d2968, size = 270816873, next_free = 0xbedf133c, prev_free = 0x40ccbbc7}
(gdb) print block[11000000]
$14 = {prev_phys_block = 0x6601c000, size = 1711390720, next_free = 0x6601c000, prev_free = 0x6601c000}
(gdb) 
(gdb) f 4
#4  0x40092fff in multi_heap_free_impl (heap=0x3ffcc6d8, p=0x3ffd8b1c) at /root/esp/esp-idf/components/heap/multi_heap.c:231
231     tlsf_free(heap->heap_data, p);
(gdb) f 7
#7  0x400deda1 in transmit_fragment (packet=0x3ffd8b1c, send_transmit_finished=true) at /root/esp/esp-idf/components/bt/host/bluedroid/hci/hci_layer.c:350
350         osi_free(packet);
(gdb) print packet
$15 = (BT_HDR *) 0x3ffd8b1c
(gdb) p packet->event
$16 = 8448
(gdb) p packet->len
$17 = 103
(gdb) p packet->offset
$18 = 4110
(gdb) p packet->layer_specific
$19 = 0
(gdb) p packet->data
$20 = 0x3ffd8b24 "Q0\f\236\037\300\246Nת\212bd\302\036wL\276\316jM\025\227J\336\024\267=ċ\217\210ʐ\027\215~7/\344$\346\253\304\021\236\327-\200\377\006\333\006\263\212FR\033\212", <incomplete sequence \353>
(gdb) p packet->data
$21 = 0x3ffd8b24 "Q0\f\236\037\300\246Nת\212bd\302\036wL\276\316jM\025\227J\336\024\267=ċ\217\210ʐ\027\215~7/\344$\346\253\304\021\236\327-\200\377\006\333\006\263\212FR\033\212", <incomplete sequence \353>
(gdb) f 8
#8  0x400dfc81 in fragment_and_dispatch (packet=0x3ffd8b1c) at /root/esp/esp-idf/components/bt/host/bluedroid/hci/packet_fragmenter.c:132
132         callbacks->fragmented(packet, true);
(gdb) locals
Undefined command: "locals".  Try "help".
(gdb) info locals
continuation_handle = 4224
max_data_size = 1021
max_packet_size = 1025
remaining_length = <optimized out>
event = <optimized out>
stream = <optimized out>
__func__ = "fragment_and_dispatch"
(gdb) p remaining_length
$22 = <optimized out>
(gdb) 
@shangke1112 
shangke1112 commented 2 weeks ago

Guru Meditation Error: Core 0 panic'ed (StoreProhibited). Exception was unhandled. StoreProhibited means writing a data to an illegal address

(gdb) print block[0] $2 = {prev_phys_block = 0x3ffd7b00, size = 25807, next_free = 0x2080c6ec, prev_free = 0x5f0063} prev_free = 0x5f0063,

prev->next_free = next;

prev = 0x5f0063 EXCVADDR: 0x005f006b LBEG : 0x4000c2e0 LEND : 0x4000c2f6 LCOUNT : 0xffffffff
0x4000c2e0: memcpy in ROM
&(prev->next_free) = 0x5f0063 + 8(offset ) = 0x005f006b

This is an illegal address; the CPU attempted to write data to the illegal address(0x5f006b) , causing the error (StoreProhibited).

    p_buf->len = (uint16_t)rand() % 255;
    // printf("\n %d \n", p_buf->len);
    // for(int i = 0; i < p_buf->len; ++i) printf("%d\n", p_buf->data[i]);
    // printf("\n\n");

    p_buf->event = (uint16_t)rand();
    p_buf->offset = (uint16_t)rand();
    p_buf->layer_specific = (uint16_t)rand();

This code cannot use random values, as it may be used in conditional judgment and byte shifting of memory, which may break the heap, and breaked heap may cause various problems.

Zakary-D commented 2 weeks ago

Guru Meditation Error: Core 0 panic'ed (StoreProhibited). Exception was unhandled. StoreProhibited means writing a data to an illegal address

(gdb) print block[0] $2 = {prev_phys_block = 0x3ffd7b00, size = 25807, next_free = 0x2080c6ec, prev_free = 0x5f0063} prev_free = 0x5f0063,

prev->next_free = next;

prev = 0x5f0063 EXCVADDR: 0x005f006b LBEG : 0x4000c2e0 LEND : 0x4000c2f6 LCOUNT : 0xffffffff 0x4000c2e0: memcpy in ROM &(prev->next_free) = 0x5f0063 + 8(offset ) = 0x005f006b

This is an illegal address; the CPU attempted to write data to the illegal address(0x5f006b) , causing the error (StoreProhibited).

    p_buf->len = (uint16_t)rand() % 255;
    // printf("\n %d \n", p_buf->len);
    // for(int i = 0; i < p_buf->len; ++i) printf("%d\n", p_buf->data[i]);
    // printf("\n\n");

    p_buf->event = (uint16_t)rand();
    p_buf->offset = (uint16_t)rand();
    p_buf->layer_specific = (uint16_t)rand();

This code cannot use random values, as it may be used in conditional judgment and byte shifting of memory, which may break the heap, and breaked heap may cause various problems.

Is it because of the lack of address checking that leads to out-of-bounds?

shangke1112 commented 2 weeks ago

I don't think so. For example:

图像 Looking at this above, if the offset is an error value,and if the processing of the receiving function modifies the content of (data+offset), it will cause a heap error.

fouzhe commented 1 week ago

Answers checklist.

  • [x] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
  • [x] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
  • [x] I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.1.3-416-gd23b7a0361

Espressif SoC revision.

ESP32D0WDQ5(revision 3)

Operating System used.

Linux

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

None

Development Kit.

ESP-WROVER-KIT

Power Supply used.

USB

What is the expected behavior?

send modified AVDTP packet to peer.

What is the actual behavior?

memory corruption and rebooting

Steps to reproduce.

1.modify code: esp-idf/components/bt/host/bluedroid/stack/avdt/avdt_ad.c

UINT8 avdt_ad_write_req(UINT8 type, tAVDT_CCB *p_ccb, tAVDT_SCB *p_scb, BT_HDR *p_buf)
{
    UINT8   tcid;

    /* get tcid from type, scb */
    tcid = avdt_ad_type_to_tcid(type, p_scb);

    srand(time(NULL));
    // p_buf[0].event = (uint16_t)rand();

    if(type == AVDT_CHAN_MEDIA){
        p_buf->event = (uint16_t)rand();
        p_buf->len = (uint16_t)rand() % 255;
        p_buf->offset = (uint16_t)rand();
        p_buf->layer_specific = (uint16_t)rand();
        for(int i = 0; i < p_buf->len; ++i) p_buf->data[i] = (uint16_t)rand();
    }

    static int dk_cnt = 0;
    if(++dk_cnt % 1000 == 0){
        dk_cnt = 0, printf("\n\n avdt_ad_write_req \n");    
        printf("%" PRIu16 " ", p_buf->event);
        printf("%" PRIu16 " ", p_buf->len);
        printf("%" PRIu16 " ", p_buf->offset);
        printf("%" PRIu16 " \n", p_buf->layer_specific);
        for(int i = 0; i < p_buf->len; ++i) printf("%" PRIu16 " ", p_buf->data[i]);
        printf("\n\n");
    }

    return L2CA_DataWrite(avdt_cb.ad.rt_tbl[avdt_ccb_to_idx(p_ccb)][tcid].lcid, p_buf);
}
  1. change the target device name of example/a2dp_source to my headphone: HUAWEI FreeBuds 4i
  2. use idf.py to build example/a2dp_source

4.flash it to ESP-WROVER-KIT and monitor it 5.about half an hour later, something get wrong and the development board rebooting

Debug Logs.

Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x40093232  PS      : 0x00060333  A0      : 0x80092e87  A1      : 0x3ffd0350  
0x40093232: remove_free_block at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:332
(inlined by) block_remove at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:380
(inlined by) block_merge_next at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:486
(inlined by) tlsf_free at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:1123

A2      : 0x3ffcc144  A3      : 0x3ffd7838  A4      : 0x3ffd7830  A5      : 0x3ffc0042  
A6      : 0x00000028  A7      : 0x00000058  A8      : 0x00000018  A9      : 0x3ffd8844  
A10     : 0x3ffd8844  A11     : 0x00000000  A12     : 0x0099009d  A13     : 0x00000004  
A14     : 0xb33fffff  A15     : 0xb33fffff  SAR     : 0x0000001c  EXCCAUSE: 0x0000001d  
EXCVADDR: 0x009900a9  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  
0x4000c2e0: memcpy in ROM
0x4000c2f6: memcpy in ROM

Backtrace: 0x4009322f:0x3ffd0350 0x40092e84:0x3ffd0370 0x40082362:0x3ffd0390 0x4009406d:0x3ffd03b0 0x400de242:0x3ffd03d0 0x400df122:0x3ffd03f0 0x400de459:0x3ffd0410 0x4010c2fa:0x3ffd0430 0x400de4b5:0x3ffd0450 0x4010d2ce:0x3ffd0470 0x4010d19a:0x3ffd0490 0x40090ad5:0x3ffd04c0
0x4009322f: remove_free_block at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:331
(inlined by) block_remove at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:380
(inlined by) block_merge_next at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:486
(inlined by) tlsf_free at /root/esp/esp-idf/components/heap/tlsf/tlsf.c:1123
0x40092e84: multi_heap_free_impl at /root/esp/esp-idf/components/heap/multi_heap.c:231
0x40082362: heap_caps_free at /root/esp/esp-idf/components/heap/heap_caps.c:388
0x4009406d: free at /root/esp/esp-idf/components/newlib/heap.c:39
0x400de242: transmit_fragment at /root/esp/esp-idf/components/bt/host/bluedroid/hci/hci_layer.c:350
0x400df122: fragment_and_dispatch at /root/esp/esp-idf/components/bt/host/bluedroid/hci/packet_fragmenter.c:132
0x400de459: event_packet_ready at /root/esp/esp-idf/components/bt/host/bluedroid/hci/hci_layer.c:338
0x4010c2fa: fixed_queue_process at /root/esp/esp-idf/components/bt/common/osi/fixed_queue.c:254
0x400de4b5: hci_downstream_data_handler at /root/esp/esp-idf/components/bt/host/bluedroid/hci/hci_layer.c:238
0x4010d2ce: osi_thread_generic_event_handler at /root/esp/esp-idf/components/bt/common/osi/thread.c:425
0x4010d19a: osi_thread_run at /root/esp/esp-idf/components/bt/common/osi/thread.c:165 (discriminator 1)
0x40090ad5: vPortTaskWrapper at /root/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

ELF file SHA256: fb53a7e2e55ccb03

Rebooting...
ets Jul 29 2019 12:21:46

More Information.

No response

@shangke1112 Hi, thanks for the follow up. As shown in the replay steps, the modification of the packet is at the AVDT layer. However, this modification of the upper layer causes the underlying HCI layer to crash when fragmenting. Is this a missing necessary check for the HCI layer? Because developers can implement an upper layer protocol without necessarily knowing the details of the lower layer. The potential mishandling should be reported instead of a crash. Besides, robust checking also helps prevent attacks.