Skip to content

Hang in os_mbuf_append #2027

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
Open
mickeyl opened this issue Apr 16, 2025 · 1 comment
Open

Hang in os_mbuf_append #2027

mickeyl opened this issue Apr 16, 2025 · 1 comment

Comments

@mickeyl
Copy link

mickeyl commented Apr 16, 2025

I'm using Nimble's L2CAP COC service (on an ESP32S3 in the form of the esp-nimble fork, but I'm pretty sure the problem is not in the Espressif-specific code) and have experienced a random stall inside NimBLE. The task watchdog triggers due to an endless loop in os_mbuf.c: os_mbuf_append:

    omp = om->om_omp;

    /* Scroll to last mbuf in the chain */
    last = om;
    while (SLIST_NEXT(last, om_next) != NULL) {
        last = SLIST_NEXT(last, om_next);
    }

Here's an example output:

D (4151) Bluetooth: Initializing done.
D (4154) TASK: CANyoneroTCP created.
D (4158) TASK: CANyoneroTCP entering code.
D (4159) TASK: CANyoneroTCP resumed.
D (4163) TCPService: Socket created (fd = 54)
E (4166) gpio: gpio_install_isr_service(506): GPIO isr service already installed
D (4170) TCPService: Socket bound to port 129
W (4178) example_eth_init: GPIO ISR handler has been already installed
I (4183) TCPService: Listening on port 129
D (4190) gdma: new group (0) at 0x3c2212e4
D (4199) gdma: new pair (0,0) at 0x3c2213d4
D (4203) gdma: new tx channel (0,0) at 0x3c2212a8
D (4208) gdma: new rx channel (0,0) at 0x3c2213f8
D (4213) spi: SPI3 use gpio matrix.
D (4216) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (4223) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (4230) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (4237) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (4244) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (4251) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (4258) w5500.mac: Using default SPI Driver
D (4263) intr_alloc: Connected src 22 to int 19 (cpu 0)
D (4268) spi_hal: eff: 26666, limit: 80000k(/0), 0 dummy, -1 delay
D (4275) spi_master: SPI3: New device added to CS0, effective clock: 26666kHz
D (4282) w5500.mac: Waiting W5500 to start & verify version...
D (4298) esp_eth: new ethernet driver @0x3fcd8a94
D (4298) esp_netif_lwip: check: remote, if=0x3fcba4a0 fn=0x420c2234
--- 0x420c2234: esp_netif_new_api at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:690

D (4299) esp_netif_objects: esp_netif_add_to_list_unsafe netif added successfully (total netifs: 1)
D (4308) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (4314) esp_eth.netif.netif_glue: e4:b0:63:92:74:87
D (4319) esp_netif_lwip: check: remote, if=0x3fcd8b14 fn=0x420c1bd4
--- 0x420c1bd4: esp_netif_set_mac_api at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:993

D (4325) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (4331) esp_eth.netif.netif_glue: ethernet attached to netif
I (4338) pp: pp rom version: e7ae62f
I (4342) net80211: net80211 rom version: e7ae62f
D (4347) nvs: nvs_open_from_partition misc 1
I (4353) wifi:wifi driver task: 3fcda8b0, prio:23, stack:3584, core=0
D (4358) nvs: nvs_open_from_partition nvs.net80211 1
D (4363) nvs: nvs_get opmode 1
D (4366) nvs: nvs_get_str_or_blob sta.ssid
D (4370) nvs: nvs_get sta.authmode 1
D (4374) nvs: nvs_get_str_or_blob sta.pswd
D (4378) nvs: nvs_get_str_or_blob sta.pmk
D (4382) nvs: nvs_get sta.chan 1
D (4385) nvs: nvs_get auto.conn 1
D (4389) nvs: nvs_get bssid.set 1
D (4392) nvs: nvs_get_str_or_blob sta.bssid
D (4396) nvs: nvs_get sta.lis_intval 2
D (4400) nvs: nvs_get sta.phym 1
D (4403) nvs: nvs_get sta.phybw 1
D (4407) nvs: nvs_get_str_or_blob sta.apsw
D (4411) nvs: nvs_get_str_or_blob sta.apinfo
D (4415) nvs: nvs_get sta.scan_method 1
D (4419) nvs: nvs_get sta.sort_method 1
D (4423) nvs: nvs_get sta.minrssi 1
D (4427) nvs: nvs_get sta.minauth 1
D (4430) nvs: nvs_get sta.pmf_e 1
D (4433) nvs: nvs_get sta.pmf_r 1
D (4437) nvs: nvs_get sta.btm_e 1
D (4440) nvs: nvs_get sta.rrm_e 1
D (4444) nvs: nvs_get sta.mbo_e 1
D (4447) nvs: nvs_get_str_or_blob ap.ssid
D (4451) nvs: nvs_get_str_or_blob ap.passwd
D (4455) nvs: nvs_get_str_or_blob ap.pmk
D (4459) nvs: nvs_get ap.chan 1
D (4463) nvs: nvs_get ap.authmode 1
D (4466) nvs: nvs_get ap.hidden 1
D (4470) nvs: nvs_get ap.max.conn 1
D (4473) nvs: nvs_get bcn.interval 2
D (4477) nvs: nvs_get ap.phym 1
D (4480) nvs: nvs_get ap.phybw 1
D (4483) nvs: nvs_get ap.sndchan 1
D (4487) nvs: nvs_get ap.pmf_e 1
D (4490) nvs: nvs_get ap.pmf_r 1
D (4493) nvs: nvs_get ap.p_cipher 1
D (4497) nvs: nvs_get lorate 1
D (4500) nvs: nvs_get_str_or_blob country
D (4504) nvs: nvs_get ap.ftm_r 1
D (4507) nvs: nvs_get sta.ft 1
D (4510) nvs: nvs_get sta.owe 1
D (4514) nvs: nvs_get sta.trans_d 1
D (4517) nvs: nvs_get sta.sae_h2e 1
D (4521) nvs: nvs_get sta.sae_pk_mode 1
D (4525) nvs: nvs_get sta.bss_retry 1
D (4528) nvs: nvs_get_str_or_blob sta.owe_data
D (4533) nvs: nvs_get sta.he_dcm 1
D (4536) nvs: nvs_get sta.he_dcm_c_tx 1
D (4540) nvs: nvs_get sta.he_dcm_c_rx 1
D (4544) nvs: nvs_get sta.he_mcs9_d 1
D (4548) nvs: nvs_get sta.he_su_b_d 1
D (4552) nvs: nvs_get sta.he_su_b_f_d 1
D (4556) nvs: nvs_get sta.he_mu_b_f_d 1
D (4560) nvs: nvs_get sta.he_cqi_f_d 1
D (4563) nvs: nvs_get_str_or_blob sta.sae_h2e_id
D (4568) nvs: nvs_get ap.sae_h2e 1
D (4571) nvs: nvs_get_str_or_blob ap.pmk_info
D (4576) nvs: nvs_get nan.phym 1
D (4579) nvs: nvs_set ap.sndchan 1 1
I (4583) wifi:wifi firmware version: cc1dd81
I (4587) wifi:wifi certification version: v7.0
I (4591) wifi:config NVS flash: enabled
I (4595) wifi:config nano formating: disabled
I (4599) wifi:Init data frame dynamic rx buffer num: 32
I (4604) wifi:Init static rx mgmt buffer num: 5
I (4608) wifi:Init management short buffer num: 32
I (4612) wifi:Init dynamic tx buffer num: 32
I (4617) wifi:Init tx cache buffer num: 32
I (4620) wifi:Init static tx FG buffer num: 2
I (4624) wifi:Init static rx buffer size: 1600
I (4629) wifi:Init static rx buffer num: 10
I (4632) wifi:Init dynamic rx buffer num: 32
I (4637) wifi_init: rx ba win: 6
I (4640) wifi_init: tcpip mbox: 32
I (4644) wifi_init: udp mbox: 6
I (4648) wifi_init: tcp mbox: 6
I (4652) wifi_init: tcp tx win: 5744
I (4656) wifi_init: tcp rx win: 5744
I (4660) wifi_init: tcp mss: 1440
I (4664) wifi_init: WiFi/LWIP prefer SPIRAM
I (4669) wifi_init: WiFi IRAM OP enabled
I (4674) wifi_init: WiFi RX IRAM OP enabled
I (4679) wifi_init: LWIP IRAM OP enabled
D (4684) esp_netif_lwip: check: remote, if=0x3fcba470 fn=0x420c2234
--- 0x420c2234: esp_netif_new_api at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:690

D (4690) esp_netif_objects: esp_netif_add_to_list_unsafe netif added successfully (total netifs: 2)
D (4699) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (4705) esp_netif_lwip: check: remote, if=0x3fcba4a0 fn=0x420c2234
--- 0x420c2234: esp_netif_new_api at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:690

D (4711) esp_netif_objects: esp_netif_add_to_list_unsafe netif added successfully (total netifs: 3)
D (4720) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (4726) esp_netif_br_glue: e4:b0:63:92:74:87
I (4731) esp_netif_br_glue: bridge netif glue attached
D (4747) event: running post ETH_EVENT:0 with handler 0x42057694 and context 0x3fcd8d3c on loop 0x3fcbe3a4
--- 0x42057694: eth_action_start at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_eth/src/esp_eth_netif_glue.c:76

D (4747) esp_eth.netif.netif_glue: eth_action_start: 0x3fcd8ce8, 0x3c0ece8c, 0, 0x3fcdf9cc, 0x3fcd8a94
D (4756) esp_netif_handlers: esp_netif action has started with netif0x3fcd8b14 from event_id=0
D (4764) esp_netif_lwip: check: remote, if=0x3fcd8b14 fn=0x420c2678
--- 0x420c2678: esp_netif_start_api at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1068

D (4771) esp_netif_lwip: esp_netif_start_api 0x3fcd8b14
D (4771) wifi:D (4776) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x3fcd8b14
filter: set rx policy=0
D (4784) esp_netif_lwip: check: local, if=0x3fcd8b14 fn=0x420c30ac
--- 0x420c30ac: esp_netif_update_default_netif_lwip at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:316

I (4786) wifi:D (4792) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcd8b14
mode : softAP (e4:b0:63:92:74:85)D (4800) esp_netif_lwip: call api in lwip: ret=0x0, give sem

D (4809) wifi:filter: set rx policy=9
I (4812) wifi:Total power save buffer number: 16
I (4816) wifi:Init max length of beacon: 752/752
I (4821) wifi:Init max length of beacon: 752/752
D (4825) event: running post ETH_EVENT:0 with handler 0x42051018 and context 0x3fcdf7ec on loop 0x3fcbe3a4
--- 0x42051018: port_action_start at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_netif/lwip/esp_netif_br_glue.c:97

D (4835) esp_netif_br_glue: eth_action_start: 0x3fcdf7a8, 0x3c0ece8c, 0, 0x3fcdf9cc, 0x3fcd8a94
D (4844) esp_netif_handlers: esp_netif action has started with netif0x3fcdf5d4 from event_id=0
D (4852) esp_netif_lwip: check: remote, if=0x3fcdf5d4 fn=0x420c2678
--- 0x420c2678: esp_netif_start_api at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1068

D (4859) esp_netif_lwip: esp_netif_start_api 0x3fcdf5d4
D (4859) APP: Started
D (4864) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x3fcdf66c
D (4873) esp_netif_lwip: DHCP server re init
D (4878) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (4883) esp_netif_br_glue: bridge netif 0x3fcdf5d4 is started
D (4889) event: running post ETH_EVENT:0 with handler 0x420192dc and context 0x3fcdf974 on loop 0x3fcbe3a4
--- 0x420192dc: BridgedEthernet::eth_event_handler(void*, char const*, long, void*) at /home/mickey/Dokumente/late/ecos/ESPenlaub/ESP32/BridgedEthernet.cpp:182

I (4899) BridgedEthernet: Started (0x3fcd8a94)
D (4904) event: running post WIFI_EVENT:40 with handler 0x420193a8 and context 0x3fcdf9ac on loop 0x3fcbe3a4
--- 0x420193a8: BridgedEthernet::wifi_event_handler(void*, char const*, long, void*) at /home/mickey/Dokumente/late/ecos/ESPenlaub/ESP32/BridgedEthernet.cpp:213

I (4914) BridgedEthernet: Unhandled event: 40
D (4919) event: running post WIFI_EVENT:12 with handler 0x42055474 and context 0x3fcdf54c on loop 0x3fcbe3a4
--- 0x42055474: wifi_default_action_ap_start at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_wifi/src/wifi_default.c:112

D (4929) wifi_init_default: wifi_start esp-netif:0x3fcdf274 event-id12
D (4935) wifi_init_default: WIFI mac address: e4 b0 63 92 74 85
D (4942) esp_netif_lwip: check: remote, if=0x3fcdf274 fn=0x420c1bd4
--- 0x420c1bd4: esp_netif_set_mac_api at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:993

D (4948) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (4948) TASK: Console created.
D (4954) esp_netif_handlers: esp_netif action has started with netif0x3fcdf274 from event_id=12
D (4957) TASK: Console entering code.
D (4966) esp_netif_lwip: check: remote, if=0x3fcdf274 fn=0x420c2678
--- 0x420c2678: esp_netif_start_api at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1068

D (4966) TASK: Console resumed.
D (4976) esp_netif_lwip: esp_netif_start_api 0x3fcdf274
D (4970) TCPService: Socket created (fd = 55)
D (4984) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x3fcdf274
D (4995) esp_netif_lwip: esp_netif_start_api Setting the lwip netif0x3fcdf30c UP
D (5002) esp_netif_lwip: check: local, if=0x3fcdf274 fn=0x420c30ac
--- 0x420c30ac: esp_netif_update_default_netif_lwip at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:316

D (5009) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcdf274
D (5015) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (5021) event: running post WIFI_EVENT:12 with handler 0x42051018 and context 0x3fcdf8b4 on loop 0x3fcbe3a4
--- 0x42051018: port_action_start at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_netif/lwip/esp_netif_br_glue.c:97

D (5021) TCPService: Socket bound to port 4242
D (5031) esp_netif_br_glue: wifi_action_start: 0x3fcdf7a8, 0x3c0ec52c, 12, 0x0
I (5036) TCPService: Listening on port 4242
D (5043) event: running post WIFI_EVENT:12 with handler 0x420193a8 and context 0x3fcdf9ac on loop 0x3fcbe3a4
--- 0x420193a8: BridgedEthernet::wifi_event_handler(void*, char const*, long, void*) at /home/mickey/Dokumente/late/ecos/ESPenlaub/ESP32/BridgedEthernet.cpp:213

I (5058) BridgedEthernet: Ready to serve connection requests
I (10884) CANyonerOS: Rollback timer expired, marking this app as confirmed.
D (10884) boot_comm: Only otadata[0] is valid
I (59959) NimBLE: GAP procedure initiated:
I (59959) NimBLE: connection parameter update; conn_handle=1 itvl_min=12 itvl_max=12 latency=0 supervision_timeout=200 min_ce_len=0 max_ce_len=0
I (59966) NimBLE:

I (60575) NimBLEServer: mtu update event; conn_handle=1 mtu=527
I (60680) NimBLEServer: subscribe event; attr_handle=8, subscribed: false
I (60710) NimBLEL2CAPChannel: L2CAP COC 0x0081 accept.
I (60710) NimBLEL2CAPChannel: L2CAP COC 0x0081 connected. Local MTU = 5000 [248], remote MTU = 1251 [1251].
W (60715) NimBLEL2CAPChannel: L2CAP COC 0x0081 connected, but local MTU is bigger than remote MTU.
D (60725) CANChannelManager: Created w/ protocolMachine 0x3fce117c.
D (60731) ProtocolMachine: Created.
D (60734) Buzzer: Playing Connected...
D (60938) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (60938) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (60941) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (60948) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (60955) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (60962) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
I (61265) NimBLEServer: subscribe event; attr_handle=8, subscribed: false
I (61265) NimBLEL2CAPChannel: L2CAP COC 0x0081 disconnected.
D (61268) ProtocolMachine: Destroyed.
D (61271) CANChannelManager: Destroyed.
D (61275) Buzzer: Playing Disconnected...
I (61479) NimBLE: GAP procedure initiated: advertise;
I (61479) NimBLE: disc_mode=2
I (61479) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
I (61487) NimBLE:

I (62950) NimBLE: GAP procedure initiated:
I (62951) NimBLE: connection parameter update; conn_handle=1 itvl_min=12 itvl_max=12 latency=0 supervision_timeout=200 min_ce_len=0 max_ce_len=0
I (62958) NimBLE:

I (63350) NimBLEServer: mtu update event; conn_handle=1 mtu=527
I (63620) NimBLEServer: subscribe event; attr_handle=8, subscribed: false
I (63665) NimBLEL2CAPChannel: L2CAP COC 0x0081 accept.
I (63666) NimBLEL2CAPChannel: L2CAP COC 0x0081 connected. Local MTU = 5000 [248], remote MTU = 1251 [1251].
W (63670) NimBLEL2CAPChannel: L2CAP COC 0x0081 connected, but local MTU is bigger than remote MTU.
D (63680) CANChannelManager: Created w/ protocolMachine 0x3fce1160.
D (63686) ProtocolMachine: Created.
D (63690) Buzzer: Playing Connected...
D (63894) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (63894) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (63897) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (63904) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (63911) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (63918) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (63950) CANChannelManager: Opening CAN...
I (63950) gpio: GPIO[38]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
D (63953) gdma: new pair (0,1) at 0x3c230c38
D (63957) gdma: new tx channel (0,1) at 0x3c230bfc
D (63962) gdma: new rx channel (0,1) at 0x3c230c5c
D (63967) spi: SPI2 use gpio matrix.
I (63970) SPI: Bus 2 initialized.
D (63974) intr_alloc: Connected src 21 to int 20 (cpu 0)
D (63980) spi_hal: eff: 800, limit: 80000k(/0), 0 dummy, -1 delay
D (63986) spi_master: SPI2: New device added to CS0, effective clock: 800kHz
I (63993) SPI: Device(CS=38 @ 800000 Hz) added to Bus 2.
D (63999) TASK: ESP-MCP251XFD.IrqHandlerTask created.
D (64004) TASK: ESP-MCP251XFD.IrqHandlerTask entering code.
D (64004) TASK: ESP-MCP251XFD.IrqHandlerTask resumed.
I (64015) gpio: GPIO[48]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:3
I (64024) ESP-MCP251XFD: Initialized
D (64028) CANController: Created (XTAL=40, FREQ=16000000, INT=48, CS=38, MISO=39, MOSI=41, SCLK=42)
D (64038) ESP-MCP251XFD: MCP251XFD device not initialized, ignoring stop request
MCP: CompFreq = 40000000
I (64047) ESP-MCP251XFD: Configuring MCP251XFD SPI transfer for 1000000 Hz

I (64055) SPI: Adjusting clock speed for Device(CS=38) to 1000000 Hz
I (64062) gpio: GPIO[38]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
D (64072) spi_hal: eff: 1000, limit: 80000k(/0), 0 dummy, -1 delay
D (64078) spi_master: SPI2: New device added to CS0, effective clock: 1000kHz
MCP: WRITE RAM OK
MCP: READ RAM OK
MCP: CONFIGURE COMPONENT CLOCK OK (CompFreq = 40000000)
MCP: CLOCK STABILIZATION OK
MCP: pComp-SPIClock = 16000000, threshold = 17000000
I (64100) ESP-MCP251XFD: Configuring MCP251XFD SPI transfer for 16000000 Hz

I (64108) SPI: Adjusting clock speed for Device(CS=38) to 16000000 Hz
I (64115) gpio: GPIO[38]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
D (64125) spi_hal: eff: 16000, limit: 80000k(/0), 0 dummy, -1 delay
D (64131) spi_master: SPI2: New device added to CS0, effective clock: 16000kHz
MCP: MOVED TO NEW SPI CLOCK SPEED: 16000000
MCP CRC IRQ CONFIGURED
MCP DEV ID READ
MCP LPM DISABLED
MCP ECC ENABLED
MCP RAM INIT
MCP GPIOs configured
I (64214) ESP-MCP251XFD: CAN 2.0B [sysclk=40000000] started w/ bitrate 500000
W (64214) ESP-MCP251XFD: IRQ events were triggered (0008) during startup. Cleaning...
W (64220) ESP-MCP251XFD: IRQ events after clearing = 0000
D (64226) ESP-MCP251XFD: Filter now set to 000, 7FF (STD)
D (64232) TASK: MCP-Receiver created.
D (64235) TASK: MCP-Receiver entering code.
D (64235) TASK: MCP-Receiver resumed.
D (64243) CANChannelManager: CAN opened.
D (64247) Channel: Created #0 for protocol 1, bitrate 500000, rxSep: 0 µS, txSep: 0 µS
D (64295) CANChannelManager: Updating Arbitration...
D (64295) ESP-MCP251XFD: Filter now set to 700, 700 (STD)
D (65360) CANChannelManager: Updating Arbitration...
D (65361) ESP-MCP251XFD: Filter now set to 17FE0000, 17FE0000 (EXT)
D (66470) CANChannelManager: Updating Arbitration...
D (66470) ESP-MCP251XFD: Filter now set to 7E8, 7FF (STD)
D (66650) CANChannelManager: Updating Arbitration...
D (66650) ESP-MCP251XFD: Filter now set to 17FE0076, 1FFFFFFF (EXT)
D (67685) CANChannelManager: Updating Arbitration...
D (67685) ESP-MCP251XFD: Filter now set to 7E8, 7FF (STD)
D (69350) CANChannelManager: Updating Arbitration...
D (69350) ESP-MCP251XFD: Filter now set to 7E9, 7FF (STD)
D (155015) adc_oneshot: new adc unit0 is created
D (155015) efuse: In EFUSE_BLK2__DATA4_REG is used 2 bits starting with 0 bit
D (155016) efuse: In EFUSE_BLK2__DATA6_REG is used 8 bits starting with 9 bit
D (155023) efuse: In EFUSE_BLK2__DATA6_REG is used 8 bits starting with 17 bit
D (155030) efuse: In EFUSE_BLK2__DATA6_REG is used 7 bits starting with 25 bit
D (155037) efuse: In EFUSE_BLK2__DATA7_REG is used 1 bits starting with 0 bit
D (155045) efuse: In EFUSE_BLK2__DATA7_REG is used 8 bits starting with 1 bit
D (155052) efuse: In EFUSE_BLK2__DATA7_REG is used 8 bits starting with 9 bit
D (155059) efuse: In EFUSE_BLK2__DATA7_REG is used 7 bits starting with 17 bit
D (155066) efuse: In EFUSE_BLK2__DATA7_REG is used 7 bits starting with 24 bit
D (155074) efuse: In EFUSE_BLK1__DATA5_REG is used 6 bits starting with 26 bit
D (155081) ADC: ADC1 Channel[0] Raw Data: 949
D (155086) ADC: ADC1 Channel[0] Cali Voltage: 796 mV
D (155091) ADC: ADC1 Channel[0] Raw Data: 949
D (155095) ADC: ADC1 Channel[0] Cali Voltage: 796 mV
D (155100) ADC: ADC1 Channel[0] Raw Data: 948
D (155104) ADC: ADC1 Channel[0] Cali Voltage: 795 mV
D (155109) ADC: ADC1 Channel[0] Raw Data: 947
D (155114) ADC: ADC1 Channel[0] Cali Voltage: 794 mV
D (155119) ADC: ADC1 Channel[0] Raw Data: 949
D (155123) ADC: ADC1 Channel[0] Cali Voltage: 796 mV
D (155128) ADC: ADC1 Channel[0] Raw Data: 949
D (155133) ADC: ADC1 Channel[0] Cali Voltage: 796 mV
D (155138) ADC: ADC1 Channel[0] Raw Data: 951
D (155142) ADC: ADC1 Channel[0] Cali Voltage: 797 mV
D (155147) ADC: ADC1 Channel[0] Raw Data: 949
D (155152) ADC: ADC1 Channel[0] Cali Voltage: 796 mV
D (155157) ADC: ADC1 Channel[0] Raw Data: 949
D (155161) ADC: ADC1 Channel[0] Cali Voltage: 796 mV
D (155166) ADC: ADC1 Channel[0] Raw Data: 949
D (155171) ADC: ADC1 Channel[0] Cali Voltage: 796 mV
D (155176) adc_oneshot: adc unit0 is deleted
I (155180) ADC: VSYS Measurement reports 12902.01 mV [avg, 10 readings]

D (155375) CANChannelManager: Closing CAN...
D (155375) TASK: MCP-Receiver will cancel...
D (155375) TASK: MCP-Receiver exited code regularly (cancel).
D (155378) TASK: MCP-Receiver cancelled.
D (155382) ESP-MCP251XFD: Shutting down...
D (155386) TASK: ESP-MCP251XFD.IrqHandlerTask will cancel...
D (155392) TASK: ESP-MCP251XFD.IrqHandlerTask exited code regularly (cancel).
D (155399) TASK: ESP-MCP251XFD.IrqHandlerTask cancelled.
I (155405) ESP-MCP251XFD: Device has entered deep sleep mode.
I (155411) ESP-MCP251XFD: Shutdown complete.
D (155416) TASK: ESP-MCP251XFD.IrqHandlerTask ~Task
I (155421) gpio: GPIO[38]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (155431) SPI: Device(CS=38 @ 16000000 Hz) removed from Bus 2.
I (155437) gpio: GPIO[41]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (155447) gpio: GPIO[39]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (155457) gpio: GPIO[42]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
D (155466) gdma: del rx channel (0,1)
D (155470) gdma: del tx channel (0,1)
D (155473) gdma: del pair (0,1)
I (155477) SPI: Bus 2 freed.
D (155480) TASK: MCP-Receiver ~Task
D (155484) CANChannelManager: CAN closed.
D (155510) CANChannelManager: Opening CAN...
I (155510) gpio: GPIO[38]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
D (155513) gdma: new pair (0,1) at 0x3c230c38
D (155517) gdma: new tx channel (0,1) at 0x3c230bfc
D (155522) gdma: new rx channel (0,1) at 0x3c230c5c
D (155527) spi: SPI2 use gpio matrix.
I (155531) SPI: Bus 2 initialized.
D (155535) intr_alloc: Connected src 21 to int 20 (cpu 0)
D (155540) spi_hal: eff: 800, limit: 80000k(/0), 0 dummy, -1 delay
D (155547) spi_master: SPI2: New device added to CS0, effective clock: 800kHz
I (155554) SPI: Device(CS=38 @ 800000 Hz) added to Bus 2.
D (155560) TASK: ESP-MCP251XFD.IrqHandlerTask created.
D (155565) TASK: ESP-MCP251XFD.IrqHandlerTask entering code.
D (155565) TASK: ESP-MCP251XFD.IrqHandlerTask resumed.
I (155576) gpio: GPIO[48]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:3
I (155586) ESP-MCP251XFD: Initialized
D (155590) CANController: Created (XTAL=40, FREQ=16000000, INT=48, CS=38, MISO=39, MOSI=41, SCLK=42)
D (155599) ESP-MCP251XFD: MCP251XFD device not initialized, ignoring stop request
MCP: CompFreq = 40000000
I (155609) ESP-MCP251XFD: Configuring MCP251XFD SPI transfer for 1000000 Hz

I (155617) SPI: Adjusting clock speed for Device(CS=38) to 1000000 Hz
I (155624) gpio: GPIO[38]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
D (155634) spi_hal: eff: 1000, limit: 80000k(/0), 0 dummy, -1 delay
D (155640) spi_master: SPI2: New device added to CS0, effective clock: 1000kHz
MCP: WRITE RAM OK
MCP: READ RAM OK
MCP: CONFIGURE COMPONENT CLOCK OK (CompFreq = 40000000)
MCP: CLOCK STABILIZATION OK
MCP: pComp-SPIClock = 16000000, threshold = 17000000
I (155662) ESP-MCP251XFD: Configuring MCP251XFD SPI transfer for 16000000 Hz

I (155670) SPI: Adjusting clock speed for Device(CS=38) to 16000000 Hz
I (155677) gpio: GPIO[38]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
D (155687) spi_hal: eff: 16000, limit: 80000k(/0), 0 dummy, -1 delay
D (155693) spi_master: SPI2: New device added to CS0, effective clock: 16000kHz
MCP: MOVED TO NEW SPI CLOCK SPEED: 16000000
MCP CRC IRQ CONFIGURED
MCP DEV ID READ
MCP LPM DISABLED
MCP ECC ENABLED
MCP RAM INIT
MCP GPIOs configured
I (155776) ESP-MCP251XFD: CAN 2.0B [sysclk=40000000] started w/ bitrate 500000
W (155777) ESP-MCP251XFD: IRQ events were triggered (0008) during startup. Cleaning...
W (155783) ESP-MCP251XFD: IRQ events after clearing = 0000
D (155789) ESP-MCP251XFD: Filter now set to 000, 7FF (STD)
D (155795) TASK: MCP-Receiver created.
D (155799) TASK: MCP-Receiver entering code.
D (155799) TASK: MCP-Receiver resumed.
D (155807) CANChannelManager: CAN opened.
D (155811) Channel: Created #0 for protocol 1, bitrate 500000, rxSep: 0 µS, txSep: 800 µS
D (155840) CANChannelManager: Updating Arbitration...
D (155840) ESP-MCP251XFD: Filter now set to 7E9, 7FF (STD)
D (157220) CANChannelManager: Updating Arbitration...
D (157220) ESP-MCP251XFD: Filter now set to 700, 700 (STD)
D (162560) CANChannelManager: Updating Arbitration...
D (162560) ESP-MCP251XFD: Filter now set to 7E9, 7FF (STD)
D (162935) CANChannelManager: Closing CAN...
D (162935) TASK: MCP-Receiver will cancel...
D (162935) TASK: MCP-Receiver exited code regularly (cancel).
D (162938) TASK: MCP-Receiver cancelled.
D (162942) ESP-MCP251XFD: Shutting down...
D (162947) TASK: ESP-MCP251XFD.IrqHandlerTask will cancel...
D (162952) TASK: ESP-MCP251XFD.IrqHandlerTask exited code regularly (cancel).
D (162960) TASK: ESP-MCP251XFD.IrqHandlerTask cancelled.
I (162965) ESP-MCP251XFD: Device has entered deep sleep mode.
I (162971) ESP-MCP251XFD: Shutdown complete.
D (162976) TASK: ESP-MCP251XFD.IrqHandlerTask ~Task
I (162981) gpio: GPIO[38]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (162991) SPI: Device(CS=38 @ 16000000 Hz) removed from Bus 2.
I (162997) gpio: GPIO[41]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (163007) gpio: GPIO[39]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (163017) gpio: GPIO[42]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
D (163026) gdma: del rx channel (0,1)
D (163030) gdma: del tx channel (0,1)
D (163033) gdma: del pair (0,1)
I (163037) SPI: Bus 2 freed.
D (163040) TASK: MCP-Receiver ~Task
D (163044) CANChannelManager: CAN closed.
D (163070) CANChannelManager: Opening CAN...
I (163070) gpio: GPIO[38]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
D (163073) gdma: new pair (0,1) at 0x3c230c38
D (163077) gdma: new tx channel (0,1) at 0x3c230bfc
D (163082) gdma: new rx channel (0,1) at 0x3c230c5c
D (163087) spi: SPI2 use gpio matrix.
I (163091) SPI: Bus 2 initialized.
D (163095) intr_alloc: Connected src 21 to int 20 (cpu 0)
D (163100) spi_hal: eff: 800, limit: 80000k(/0), 0 dummy, -1 delay
D (163107) spi_master: SPI2: New device added to CS0, effective clock: 800kHz
I (163114) SPI: Device(CS=38 @ 800000 Hz) added to Bus 2.
D (163120) TASK: ESP-MCP251XFD.IrqHandlerTask created.
D (163125) TASK: ESP-MCP251XFD.IrqHandlerTask entering code.
D (163125) TASK: ESP-MCP251XFD.IrqHandlerTask resumed.
I (163136) gpio: GPIO[48]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:3
I (163146) ESP-MCP251XFD: Initialized
D (163150) CANController: Created (XTAL=40, FREQ=16000000, INT=48, CS=38, MISO=39, MOSI=41, SCLK=42)
D (163159) ESP-MCP251XFD: MCP251XFD device not initialized, ignoring stop request
MCP: CompFreq = 40000000
I (163169) ESP-MCP251XFD: Configuring MCP251XFD SPI transfer for 1000000 Hz

I (163177) SPI: Adjusting clock speed for Device(CS=38) to 1000000 Hz
I (163184) gpio: GPIO[38]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
D (163194) spi_hal: eff: 1000, limit: 80000k(/0), 0 dummy, -1 delay
D (163200) spi_master: SPI2: New device added to CS0, effective clock: 1000kHz
MCP: WRITE RAM OK
MCP: READ RAM OK
MCP: CONFIGURE COMPONENT CLOCK OK (CompFreq = 40000000)
MCP: CLOCK STABILIZATION OK
MCP: pComp-SPIClock = 16000000, threshold = 17000000
I (163222) ESP-MCP251XFD: Configuring MCP251XFD SPI transfer for 16000000 Hz

I (163230) SPI: Adjusting clock speed for Device(CS=38) to 16000000 Hz
I (163238) gpio: GPIO[38]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
D (163247) spi_hal: eff: 16000, limit: 80000k(/0), 0 dummy, -1 delay
D (163254) spi_master: SPI2: New device added to CS0, effective clock: 16000kHz
MCP: MOVED TO NEW SPI CLOCK SPEED: 16000000
MCP CRC IRQ CONFIGURED
MCP DEV ID READ
MCP LPM DISABLED
MCP ECC ENABLED
MCP RAM INIT
MCP GPIOs configured
I (163336) ESP-MCP251XFD: CAN 2.0B [sysclk=40000000] started w/ bitrate 500000
W (163337) ESP-MCP251XFD: IRQ events were triggered (0008) during startup. Cleaning...
W (163343) ESP-MCP251XFD: IRQ events after clearing = 0000
D (163349) ESP-MCP251XFD: Filter now set to 000, 7FF (STD)
D (163355) TASK: MCP-Receiver created.
D (163358) TASK: MCP-Receiver entering code.
D (163358) TASK: MCP-Receiver resumed.
D (163367) CANChannelManager: CAN opened.
D (163371) Channel: Created #0 for protocol 1, bitrate 500000, rxSep: 0 µS, txSep: 800 µS
D (163610) CANChannelManager: Updating Arbitration...
D (163610) ESP-MCP251XFD: Filter now set to 7E9, 7FF (STD)
E (172618) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
E (172618) task_wdt:  - IDLE0 (CPU 0)
E (172618) task_wdt: Tasks currently running:
E (172618) task_wdt: CPU 0: nimble_host
E (172618) task_wdt: CPU 1: IDLE1
E (172618) task_wdt: Print CPU 0 (current core) backtrace


Backtrace: 0x420438D3:0x3FCB02C0 0x42043CF0:0x3FCB02E0 0x40379351:0x3FCB0310 0x420345CA:0x3FCCDBF0 0x42034699:0x3FCCDC20 0x4203880C:0x3FCCDC50 0x4202CA8A:0x3FCCDC80 0x4202BF49:0x3FCCDCB0 0x4202BF5B:0x3FCCDCD0 0x420B9E7B:0x3FCCDCF0 0x40378E96:0x3FCCDD10 0x4202690E:0x3FCCDD30 0x403847B5:0x3FCCDD50
--- 0x420438d3: task_wdt_timeout_handling at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_system/task_wdt/task_wdt.c:441
--- 0x42043cf0: task_wdt_isr at /home/mickey/Dokumente/late/ecos/esp-idf/components/esp_system/task_wdt/task_wdt.c:515
--- 0x40379351: _xt_lowint1 at /home/mickey/Dokumente/late/ecos/esp-idf/components/xtensa/xtensa_vectors.S:1240
--- 0x420345ca: os_mbuf_append at /home/mickey/Dokumente/late/ecos/esp-idf/components/bt/host/nimble/nimble/porting/nimble/src/os_mbuf.c:411
--- 0x42034699: os_mbuf_appendfrom at /home/mickey/Dokumente/late/ecos/esp-idf/components/bt/host/nimble/nimble/porting/nimble/src/os_mbuf.c:482
--- 0x4203880c: ble_l2cap_coc_rx_fn at /home/mickey/Dokumente/late/ecos/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_l2cap_coc.c:258
--- 0x4202ca8a: ble_hs_hci_evt_acl_process at /home/mickey/Dokumente/late/ecos/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_hci_evt.c:1124
--- 0x4202bf49: ble_hs_process_rx_data_queue at /home/mickey/Dokumente/late/ecos/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:243
--- 0x4202bf5b: ble_hs_event_rx_data at /home/mickey/Dokumente/late/ecos/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:540
--- 0x420b9e7b: npl_freertos_event_run at /home/mickey/Dokumente/late/ecos/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/src/npl_os_freertos.c:451
--- 0x40378e96: ble_npl_event_run at /home/mickey/Dokumente/late/ecos/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:185
---  (inlined by) nimble_port_run at /home/mickey/Dokumente/late/ecos/esp-idf/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:248
--- 0x4202690e: NimBLEDevice::host_task(void*) at /home/mickey/Dokumente/late/ecos/esp-nimble-cpp/src/NimBLEDevice.cpp:862
--- 0x403847b5: vPortTaskWrapper at /home/mickey/Dokumente/late/ecos/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:134


E (177618) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
E (177618) task_wdt:  - IDLE0 (CPU 0)
E (177618) task_wdt: Tasks currently running:
E (177618) task_wdt: CPU 0: nimble_host
E (177618) task_wdt: CPU 1: IDLE1
E (177618) task_wdt: Print CPU 0 (current core) backtrace

In which case can that happen? Is the system out of mbufs? If so, would it be possible to rather emit an error instead of hanging in this endless loop?

That said, it is possible to get a minimum buffer watermark like w/ heap memory? Because the static mbuf configuration seems like pretty much like "guessing" to me?
@mickeyl mickeyl mentioned this issue Apr 16, 2025
Closed
3 tasks
@mickeyl mickeyl mentioned this issue Apr 28, 2025
Open
@sjanc
Copy link
Contributor

sjanc commented May 12, 2025

hmm this looks like memory corruption (broken mbuf's slist?)

there are some unfixed locking issues in CoC code (#1955) that could results in races, possibly causing such corruption

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@mickeyl @sjanc