lld_pdu.c assertions running BLE example on `esp32` chip

[brandonros]

 $ cargo "+esp" run --example ble --release --target xtensa-esp32-none-elf --features "esp32,ble"
   Compiling esp-wifi v0.1.0 (/Users/brandonros/Desktop/esp-wifi)
    Finished release [optimized] target(s) in 1.66s
     Running `espflash --speed 921600 --monitor target/xtensa-esp32-none-elf/release/examples/ble`
Detected 2 serial ports. Ports which match a known common dev board are highlighted.

Serial port: /dev/tty.usbserial-02728E37
Connecting...

WARN setting baud rate higher than 115200 can cause issues.
Chip type:         ESP32 (revision 3)
Crystal frequency: 40MHz
Flash size:        16MB
Features:          WiFi, BT, Dual Core, 240MHz, Coding Scheme None
MAC address:       94:b9:7e:57:4b:18
App/part. size:    294688/16711680 bytes, 1.76%
[00:00:00] ########################################      16/16      segment 0x1000                                                                                                                                              [00:00:00] ########################################       1/1       segment 0x8000                                                                                                                                              [00:00:03] ########################################     156/156     segment 0x10000                                                                                                                                             
Flashing has completed!
Commands:
    CTRL+R    Reset chip
    CTRL+C    Exit

ets Jul 29 2019 12:21:46
rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0048,len:12
ho 0 tail 12 room 4
load:0x3fff0054,len:4800
load:0x40078000,len:17448
0x40078000 - r_rwip_reset
    at ??:??
load:0x4007c428,len:4840
0x4007c428 - r_rwip_reset
    at ??:??
entry 0x4007c6a0
0x4007c6a0 - r_rwip_reset
    at ??:??
WARN - coex_register_bt_cb 0x40081698
0x40081698 - coex_bt_callback
    at ??:??
WARN - coex_schm_register_btdm_callback 0x400df318
0x400df318 - coex_schm_btdm_callback
    at ??:??
WARN - coex_wifi_channel_get
Ok(CommandComplete { num_packets: 5, opcode: 3075, data: [0] })
Ok(CommandComplete { num_packets: 5, opcode: 8198, data: [0] })
Ok(CommandComplete { num_packets: 5, opcode: 8200, data: [0] })
Ok(CommandComplete { num_packets: 5, opcode: 8202, data: [0] })
started advertising
ASSERT_PARAM(9 0), in lld_pdu.c at line 605
Exception occured Illegal Context { PC: 400816df, PS: 60c11, A0: 80081ac5, A1: 3ffff1e0, A2: 0, A3: 9, A4: 0, A5: 3f4110da, A6: 25d, A7: fffffffc, A8: 8000814b, A9: 3ffff150, A10: 0, A11: 3ffff173, A12: 3ffff11f, A13: 35, A14: 0, A15: 3ffff124, SAR: 4, EXCCAUSE: 0, EXCVADDR: 0, LBEG: 400819cd, LEND: 400819d5, LCOUNT: 0, THREADPTR: 0, SCOMPARE1: 0, BR: 0, ACCLO: 0, ACCHI: 0, M0: 0, M1: 0, M2: 0, M3: 0, F64R_LO: 0, F64R_HI: 0, F64S: 0, FCR: 0, FSR: 80, F0: 433b8000, F1: 426c0000, F2: 43800000, F3: 0, F4: 0, F5: 0, F6: 0, F7: 0, F8: 0, F9: 0, F10: 0, F11: 0, F12: 0, F13: 0, F14: 0, F15: 0 }
0x400816df
0x400816df - r_assert
    at ??:??
0x40081ac5
0x40081ac5 - r_assert_param
    at ??:??
0x40086364
0x40086364 - r_lld_pdu_rx_handler
    at ??:??
0x40084be4
0x40084be4 - r_lld_evt_end
    at ??:??
0x400848f5
0x400848f5 - r_lld_evt_end_isr
    at ??:??
0x400870b1
0x400870b1 - r_rwble_isr
    at ??:??
0x40088432
0x40088432 - r_rwbtdm_isr_wrapper
    at ??:??
0x400d3521
0x400d3521 - RWBLE
    at ??:??
0x4008ba44
0x4008ba44 - _ZN14esp_hal_common9interrupt8vectored16handle_interrupt17hd4ff79f68e7aaaf8E
    at ??:??
0x4008b9fd
0x4008b9fd - _ZN14esp_hal_common9interrupt8vectored17handle_interrupts17h66a646a6760229b5E
    at ??:??
0x4008af91
0x4008af91 - __level_3_interrupt
    at ??:??
0x4008bc92
0x4008bc92 - .RestoreContext
    at ??:??
ets Jul 29 2019 12:21:46
rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0048,len:12
ho 0 tail 12 room 4
load:0x3fff0054,len:4800
load:0x40078000,len:17448
0x40078000 - r_rwip_reset
    at ??:??
load:0x4007c428,len:4840
0x4007c428 - r_rwip_reset
    at ??:??
entry 0x4007c6a0
0x4007c6a0 - r_rwip_reset
    at ??:??
WARN - coex_register_bt_cb 0x40081698
0x40081698 - coex_bt_callback
    at ??:??
WARN - coex_schm_register_btdm_callback 0x400df318
0x400df318 - coex_schm_btdm_callback
    at ??:??
WARN - coex_wifi_channel_get
Ok(CommandComplete { num_packets: 5, opcode: 3075, data: [0] })
Ok(CommandComplete { num_packets: 5, opcode: 8198, data: [0] })
Ok(CommandComplete { num_packets: 5, opcode: 8200, data: [0] })
Ok(CommandComplete { num_packets: 5, opcode: 8202, data: [0] })
started advertising
INFO - polled: Some(AsyncData(AclPacket { handle: 0, boundary_flag: FirstAutoFlushable, bc_flag: PointToPoint, data: [3, 0, 4, 0, 2, f, 2] }))
INFO - att: ExchangeMtu { mtu: 20f }
INFO - Requested MTU 527, returning 23
INFO - src_handle 0
INFO - data [3, 17, 0]
INFO - encoded_l2cap [3, 0, 4, 0, 3, 17, 0]
INFO - writing [2, 0, 20, 7, 0, 3, 0, 4, 0, 3, 17, 0]
INFO - polled: Some(Event(NumberOfCompletedPackets { number_of_connection_handles: 1, connection_handles: 0, completed_packets: 1 }))
INFO - polled: Some(AsyncData(AclPacket { handle: 0, boundary_flag: FirstAutoFlushable, bc_flag: PointToPoint, data: [3, 0, 4, 0, a, 3, 0] }))
INFO - att: ReadReq { handle: 3 }
INFO - src_handle 0
INFO - data [b, 48, 65, 6c, 6c, 6f, 20, 42, 61, 72, 65, 2d, 4d, 65, 74, 61, 6c, 20, 42, 4c, 45]
INFO - encoded_l2cap [15, 0, 4, 0, b, 48, 65, 6c, 6c, 6f, 20, 42, 61, 72, 65, 2d, 4d, 65, 74, 61, 6c, 20, 42, 4c, 45]
INFO - writing [2, 0, 20, 19, 0, 15, 0, 4, 0, b, 48, 65, 6c, 6c, 6f, 20, 42, 61, 72, 65, 2d, 4d, 65, 74, 61, 6c, 20, 42, 4c, 45]
INFO - polled: Some(Event(NumberOfCompletedPackets { number_of_connection_handles: 1, connection_handles: 0, completed_packets: 1 }))
ASSERT_PARAM(0 182), in lld_pdu.c at line 605
Exception occured Illegal Context { PC: 400816df, PS: 60811, A0: 80081ac5, A1: 3ffd8e80, A2: 0, A3: 0, A4: b6, A5: 3f4110da, A6: 25d, A7: fffffffc, A8: 8000814b, A9: 3ffd8df0, A10: 0, A11: 3ffd8e13, A12: 3ffd8dbf, A13: 35, A14: 0, A15: 3ffd8dc4, SAR: 4, EXCCAUSE: 0, EXCVADDR: 0, LBEG: 400819cd, LEND: 400819d5, LCOUNT: 0, THREADPTR: 0, SCOMPARE1: 0, BR: 0, ACCLO: 0, ACCHI: 0, M0: 0, M1: 0, M2: 0, M3: 0, F64R_LO: 0, F64R_HI: 0, F64S: 0, FCR: 0, FSR: 0, F0: 0, F1: 0, F2: 0, F3: 0, F4: 0, F5: 0, F6: 0, F7: 0, F8: 0, F9: 0, F10: 0, F11: 0, F12: 0, F13: 0, F14: 0, F15: 0 }
0x400816df
0x400816df - r_assert
    at ??:??
0x40081ac5
0x40081ac5 - r_assert_param
    at ??:??
0x40086364
0x40086364 - r_lld_pdu_rx_handler
    at ??:??
0x40084be4
0x40084be4 - r_lld_evt_end
    at ??:??
0x400848f5
0x400848f5 - r_lld_evt_end_isr
    at ??:??
0x400870b1
0x400870b1 - r_rwble_isr
    at ??:??
0x40088432
0x40088432 - r_rwbtdm_isr_wrapper
    at ??:??
0x400d3521
0x400d3521 - RWBLE
    at ??:??
0x4008ba44
0x4008ba44 - _ZN14esp_hal_common9interrupt8vectored16handle_interrupt17hd4ff79f68e7aaaf8E
    at ??:??
0x4008b9fd
0x4008b9fd - _ZN14esp_hal_common9interrupt8vectored17handle_interrupts17h66a646a6760229b5E
    at ??:??
0x4008af91
0x4008af91 - __level_3_interrupt
    at ??:??
0x4008bc92
0x4008bc92 - .RestoreContext
    at ??:??

[bjoernQ]

Thanks for reporting this. This might be caused by a miscompilation / misoptimization but 1.65 should hopefully fix a few things.

I'd suggest let's wait for 1.65 and in the meantime, you might want to try different optimization levels which might or might not help

[brandonros]

started advertising
INFO - polled: Some(AsyncData(AclPacket { handle: 0, boundary_flag: FirstAutoFlushable, bc_flag: PointToPoint, data: [3, 0, 4, 0, 2, f, 2] }))
INFO - att: ExchangeMtu { mtu: 20f }
INFO - Requested MTU 527, returning 23
INFO - src_handle 0
INFO - data [3, 17, 0]
INFO - encoded_l2cap [3, 0, 4, 0, 3, 17, 0]
INFO - writing [2, 0, 20, 7, 0, 3, 0, 4, 0, 3, 17, 0]
INFO - polled: Some(Event(NumberOfCompletedPackets { number_of_connection_handles: 1, connection_handles: 0, completed_packets: 1 }))
ASSERT_PARAM(0 182), in lld_pdu.c at line 605
 
 
!! A panic occured in '/Users/brandonros/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/xtensa-lx-rt-0.13.0/src/exception/esp32.rs', at line 102, column 5
 
PanicInfo {
    payload: Any { .. },
    message: Some(
        Exception: Illegal, Context { PC: 400816df, PS: 00060411, A0: 80081ac5, A1: 3ffff120, A2: 00000000, A3: 00000000, A4: 000000b6, A5: 3f4115de, A6: 0000025d, A7: fffffffc, A8: 8000814b, A9: 3ffff090, A10: 00000000, A11: 3ffff0b3, A12: 3ffff05f, A13: 00000035, A14: 00000000, A15: 3ffff064, SAR: 00000004, EXCCAUSE: 00000000, EXCVADDR: 00000000, LBEG: 400819cd, LEND: 400819d5, LCOUNT: 00000000, THREADPTR: 00000000, SCOMPARE1: 00000000, BR: 00000000, ACCLO: 00000000, ACCHI: 00000000, M0: 00000000, M1: 00000000, M2: 00000000, M3: 00000000, F64R_LO: 00000000, F64R_HI: 00000000, F64S: 00000000, FCR: 00000000, FSR: 00000080, F0: 433b8000, F1: 426c0000, F2: 43800000, F3: 00000000, F4: 00000000, F5: 00000000, F6: 00000000, F7: 00000000, F8: 00000000, F9: 00000000, F10: 00000000, F11: 00000000, F12: 00000000, F13: 00000000, F14: 00000000, F15: 00000000 },
    ),
    location: Location {
        file: "/Users/brandonros/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/xtensa-lx-rt-0.13.0/src/exception/esp32.rs",
        line: 102,
        col: 5,
    },
    can_unwind: true,
}
 
Backtrace:
 
0x4008ba29
0x4008ba29 - __exception
    at ??:??
0x4008bd25
0x4008bd25 - __naked_kernel_exception
    at ??:??
0x40040003
0x40040003 - r_ld_sched_sniff_add
    at ??:??
0x400816df
0x400816df - r_assert
    at ??:??
0x40086364
0x40086364 - r_lld_pdu_rx_handler
    at ??:??
0x40084be4
0x40084be4 - r_lld_evt_end
    at ??:??
0x400848f5
0x400848f5 - r_lld_evt_end_isr
    at ??:??
0x400870b1
0x400870b1 - r_rwble_isr
    at ??:??
0x40088432
0x40088432 - r_rwbtdm_isr_wrapper
    at ??:??
0x400d3751
0x400d3751 - RWBLE
    at ??:??

get this after compiling, flashing, running, grabbing iPhone, connecting with BT Inspector app

could you elaborate more on what optimization levels I should try? really love the progress you've made in this area and want to try to work around this blocker

[profile.dev]
opt-level = 0

[profile.release]
opt-level = 3

or something more custom?

[brandonros]

ets Jul 29 2019 12:21:46
rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0048,len:12
ho 0 tail 12 room 4
load:0x3fff0054,len:4800
load:0x40078000,len:17448
0x40078000 - r_rwip_reset
    at ??:??
load:0x4007c428,len:4840
0x4007c428 - r_rwip_reset
    at ??:??
entry 0x4007c6a0
0x4007c6a0 - r_rwip_reset
    at ??:??
WARN - coex_register_bt_cb 0x40081698
0x40081698 - coex_bt_callback
    at ??:??
WARN - coex_schm_register_btdm_callback 0x400df714
0x400df714 - coex_schm_btdm_callback
    at ??:??
WARN - coex_wifi_channel_get
started advertising
INFO - polled: Some(AsyncData(AclPacket { handle: 0, boundary_flag: FirstAutoFlushable, bc_flag: PointToPoint, data: [3, 0, 4, 0, 2, f, 2] }))
INFO - att: ExchangeMtu { mtu: 20f }
INFO - Requested MTU 527, returning 23
INFO - src_handle 0
INFO - data [3, 17, 0]
INFO - encoded_l2cap [3, 0, 4, 0, 3, 17, 0]
INFO - writing [2, 0, 20, 7, 0, 3, 0, 4, 0, 3, 17, 0]
INFO - polled: Some(Event(NumberOfCompletedPackets { number_of_connection_handles: 1, connection_handles: 0, completed_packets: 1 }))
ASSERT_PARAM(1 2), in lld_evt.c at line 2061
 
 
!! A panic occured in '/Users/brandonros/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/xtensa-lx-rt-0.13.0/src/exception/esp32.rs', at line 102, column 5
 
PanicInfo {
    payload: Any { .. },
    message: Some(
        Exception: Illegal, Context { PC: 400816df, PS: 00060011, A0: 80081ac5, A1: 3ffff140, A2: 00000000, A3: 00000001, A4: 00000002, A5: 3f411326, A6: 0000080d, A7: fffffffb, A8: 8000814b, A9: 3ffff0b0, A10: 00000000, A11: 3ffff0d4, A12: 3ffff07f, A13: 00000031, A14: 00000000, A15: 3ffff085, SAR: 00000004, EXCCAUSE: 00000000, EXCVADDR: 00000000, LBEG: 400819cd, LEND: 400819d5, LCOUNT: 00000000, THREADPTR: 00000000, SCOMPARE1: 00000000, BR: 00000000, ACCLO: 00000000, ACCHI: 00000000, M0: 00000000, M1: 00000000, M2: 00000000, M3: 00000000, F64R_LO: 00000000, F64R_HI: 00000000, F64S: 00000000, FCR: 00000000, FSR: 00000080, F0: 433b8000, F1: 426c0000, F2: 43800000, F3: 00000000, F4: 00000000, F5: 00000000, F6: 00000000, F7: 00000000, F8: 00000000, F9: 00000000, F10: 00000000, F11: 00000000, F12: 00000000, F13: 00000000, F14: 00000000, F15: 00000000 },
    ),
    location: Location {
        file: "/Users/brandonros/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/xtensa-lx-rt-0.13.0/src/exception/esp32.rs",
        line: 102,
        col: 5,
    },
    can_unwind: true,
}
 
Backtrace:
 
0x4008ba29
0x4008ba29 - __default_exception
    at ??:??
0x4008bd25
0x4008bd25 - __naked_user_exception
    at ??:??
0x40040003
0x40040003 - r_ld_sched_sniff_add
    at ??:??
0x400816df
0x400816df - r_assert
    at ??:??
0x40084c3a
0x40084c3a - r_lld_evt_end
    at ??:??
0x400848f5
0x400848f5 - r_lld_evt_end_isr
    at ??:??
0x400870b1
0x400870b1 - r_rwble_isr
    at ??:??
0x40088432
0x40088432 - r_rwbtdm_isr_wrapper
    at ??:??
0x400d3751
0x400d3751 - RWBLE
    at ??:??
0x4008ba10
0x4008ba10 - _ZN14esp_hal_common9interrupt8vectored16handle_interrupt17h9bc01e6c8b9ab782E
    at ??:??

another just in case it helps

[bjoernQ]

You might want to try opt-levels 1,2,"s" and "z" for release (in debug things tend to be way to slow so you really want release builds).

The assert happens in the closed-source driver (which I don't have access to). What happens according to the backtrace is that an RWBLE interrupt is raised and we call the registered callback (inside the driver). For some reason it's unhappy about something - that's all I see currently