[USB][ABORT][v4.4.2] root_port_handle_events() hits HUB_DRIVER_STATE_ROOT_RECOVERY (IDFGH-8214)

[chipweinberger]

General issue report

ESP-IDF v4.4.2 ESP32-S3

See original issue: https://github.com/espressif/esp-idf/issues/8748 for more details.

Esp USB stack sometimes crashes (~5% chance) when unplugging a USB device.

The abort happens because we are in HUB_DRIVER_STATE_ROOT_RECOVERY state, which is not handled by root_port_handle_events() switch statement.

Logs:

I (109451) : e1 : [pd usbh] USB TRANSFER FAILED - no device
e2 : [pd usbh [device]] submitTransferAndWait() failed
e3 : [pd midi usb IN] xfer IN task: DEV GONE

I (109471) pd midi usb IN: xferInTask_loop ended. wait for usb replug.
I (109471) pd usbh: cancelAllTransfers()
I (109481) pd_buzz: USB Device Removed Sound
buzz F 4 698Hz 100ms
E (109451) USBH: Device 1 gone
W (109491) pd usbh: [client task] DEV_GONE dev_hdl: 0x3debc3f0
W (109491) pd usbh: [close device] closing, dev_hdl: 0x3debc3f0

abort() was called at PC 0x4207d12a on core 1

Backtrace:0x4207d12a:0x3fcd4770 0x4207dfca:0x3fcd47a0 0x420772a8:0x3fcd47d0 0x4203dd68:0x3fcd4800 0x40388252:0x3fcd4830 

0x4207d12a: root_port_handle_events at /esp-idf/components/usb/hub.c:789

0x4207dfca: hub_process at /esp-idf/components/usb/hub.c:994

0x420772a8: usb_host_lib_handle_events at /esp-idf/components/usb/usb_host.c:514

0x4203dd68: PDUsbHostService::usbHostTaskLoop(void*) at /jcommon/usb/PDUsbHostService.cpp:59 (discriminator 11)

0x40388252: vPortTaskWrapper at /esp-idf/components/freertos/port/xtensa/port.c:131

[chipweinberger]

From @Dazza0 from previous thread.

@chipweinberger Seems like a double HCD Port event. The hub only goes into the HUB_DRIVER_STATE_ROOT_RECOVERY state when the root port has an error (e.g., DISCONNECTION, ERROR, OVERCURRENT).

However, while hub driver is recovering the root port, there's another HCD_PORTEVENT... occurring, thus leading to the switch case calling the abort: Could you log what port_event is happening when the abort() is called?

Note: this abort happens when I unplug the USB device.

Do you know if this is happening every time you unplug the USB device? Usually, when you first unblock the USB device, a HCD_PORT_EVENT_DISCONNECTION event occurs which puts Hub driver into recovery. However, once disconnected, there shouldn't be any further HCD Port events.

So maybe there's an edge case missing where an HCD_PORT_EVENT_ERROR occurs first, followed rapidly by a HCD_PORT_EVENT_DISCONNECTION (it could happen the disconnection happens slowly).

@chipweinberger BTW, could you also open a separate Github issue to track this. I want to current issue to track the usb_transfer_t status feature mentioned above.

Answers:

is happening every time you unplug the USB device?

No. It's about 1 out of 20 unplugs (rough guess). Note: I sometimes plug and unplug very rapidly (trying to cause failures, for testing), but I can't remember if that is a prerequisite.

Could you log what port_event

Yes, I'll try this today. Is there a specific line of code to insert this log?

[chipweinberger]

I finally repro'd it again!! It definitely takes awhile to repro (5+ minutes of trying). I was about to give up!

So the issue is: we are in HUB_DRIVER_STATE_ROOT_RECOVERY state, which is not handled by root_port_handle_events() switch statement, when I unplug the device.

First things first: I was only able to repro it with reinitAfterFailure=true. Maybe with more trying I could repro it while it's false. I call this code whenever a USB transfer fails (for any reason). Pretty self explanatory.

                // Not sure which one is more reliable...
                // https://github.com/espressif/esp-idf/issues/8748
                bool reinitAfterFailure = true;
                if (reinitAfterFailure) {

                    // uninitializes everything
                    PDUsbHostService::uninitialize(error);
                    if (is_fail(*error)){
                        pd_raise_uie_e3("usbUninitialize", error);
                    }

                } else {

                    // This will cause the midi-IN task to stop as well
                    PDUsbHostService::cancelAllTransfers();

                    // This will cause the usbh device to re-open
                    PDUsbHostService::closeAllDevices(error);
                    if (is_fail(*error)){
                        pd_raise_uie_e3("closeAllUsbDevices", error);
                    }
                }

I added logs to port_event & hal_port_evt with these enum values, to be sure:

typedef enum {
    USBH_HAL_PORT_EVENT_NONE = 0,               /**< No event occurred, or could not decode interrupt */
    USBH_HAL_PORT_EVENT_CHAN = 1,               /**< A channel event has occurred. Call the the channel event handler instead */
    USBH_HAL_PORT_EVENT_CONN = 2,               /**< The host port has detected a connection */
    USBH_HAL_PORT_EVENT_DISCONN = 3,            /**< The host port has been disconnected */
    USBH_HAL_PORT_EVENT_ENABLED = 4,            /**< The host port has been enabled (i.e., connected to a device that has been reset. Started sending SOFs) */
    USBH_HAL_PORT_EVENT_DISABLED = 5,           /**< The host port has been disabled (no more SOFs). Could be due to disable/reset request, or a port error (e.g. port babble condition. See 11.8.1 of USB2.0 spec) */
    USBH_HAL_PORT_EVENT_OVRCUR = 6,             /**< The host port has encountered an overcurrent condition */
    USBH_HAL_PORT_EVENT_OVRCUR_CLR = 7,         /**< The host port has been cleared of the overcurrent condition */
} usbh_hal_port_event_t;

typedef enum {
    HCD_PORT_EVENT_NONE = 0,            /**< No event has occurred. Or the previous event is no longer valid */
    HCD_PORT_EVENT_CONNECTION = 1,      /**< A device has been connected to the port */
    HCD_PORT_EVENT_DISCONNECTION = 2,   /**< A device disconnection has been detected */
    HCD_PORT_EVENT_ERROR = 3,           /**< A port error has been detected. Port is now HCD_PORT_STATE_RECOVERY  */
    HCD_PORT_EVENT_OVERCURRENT = 4,     /**< Overcurrent detected on the port. Port is now HCD_PORT_STATE_RECOVERY */
} hcd_port_event_t;

And this logging code to hcd.c

static void intr_hdlr_main(void *arg)
{
    port_t *port = (port_t *) arg;
    bool yield = false;

    HCD_ENTER_CRITICAL_ISR();
    usbh_hal_port_event_t hal_port_evt = usbh_hal_decode_intr(port->hal);

    // log here
    esp_rom_printf(DRAM_STR("hal:%u\n"), hal_port_evt);

    if (hal_port_evt == USBH_HAL_PORT_EVENT_CHAN) {
        //Channel event. Cycle through each pending channel
        usbh_hal_chan_t *chan_obj = usbh_hal_get_chan_pending_intr(port->hal);
        while (chan_obj != NULL) {
            pipe_t *pipe = (pipe_t *)usbh_hal_chan_get_context(chan_obj);
            hcd_pipe_event_t event = _intr_hdlr_chan(pipe, chan_obj, &yield);
            //Run callback if a pipe event has occurred and the pipe also has a callback
            if (event != HCD_PIPE_EVENT_NONE && pipe->callback != NULL) {
                HCD_EXIT_CRITICAL_ISR();
                yield |= pipe->callback((hcd_pipe_handle_t)pipe, event, pipe->callback_arg, true);
                HCD_ENTER_CRITICAL_ISR();
            }
            //Check for more channels with pending interrupts. Returns NULL if there are no more
            chan_obj = usbh_hal_get_chan_pending_intr(port->hal);
        }
    } else if (hal_port_evt != USBH_HAL_PORT_EVENT_NONE) {  //Port event

        hcd_port_event_t port_event = _intr_hdlr_hprt(port, hal_port_evt, &yield);

        // log here
        esp_rom_printf(DRAM_STR("port:%u\n"), port_event);

        if (port_event != HCD_PORT_EVENT_NONE) {
            port->last_event = port_event;
            port->flags.event_pending = 1;
            if (port->callback != NULL) {
                HCD_EXIT_CRITICAL_ISR();
                yield |= port->callback((hcd_port_handle_t)port, port_event, port->callback_arg, true);
                HCD_ENTER_CRITICAL_ISR();
            }
        }
    }
    HCD_EXIT_CRITICAL_ISR();

    if (yield) {
        portYIELD_FROM_ISR();
    }
}

Logs:

I (10834) pd usbh: usb_host_interface_claim(0x3deb84a0, deviceHandle:0x3deb85b0 bInterfaceNumber: 1 bAlternateSetting: 0)
I (10834) pd usbh: [host task] usb_host_lib_handle_events()
I (10854) pd midi usb: epAddrIn: 129
I (10864) pd midi usb IN: xTaskCreate xferInTask_loop
I (10864) pd midi usb: epAddrOut: 1
I (10864) pd log: allocated TLS for thread: xferInTask_loop. 0x3fcd8dcc.
I (10864) pd midi usb OUT: xTaskCreate midi_usb_tx_task
I (10864) pd midi usb IN: xferInTask_loop started
hal:1
I (10884) pd midi usb OUT: allocate msg queue: 44000 bytes
I (10894) pd midi usb IN: first Midi In. length: 64, 0x4a
W (10904) pd issues: RAISE - [Atypical] | usbMidiJunk
I (10904) pd_buzz: USB Device Inserted Sound
W (10914) pd midi usb IN: ignore junk. superhuman? no  (15ms) junk? yesbuzz C 4 523Hz 100ms

W (10924) pd midi usb IN: 10.887 (usb open time)
junk: 10.902 | Cb:10 Ch:4  | Note Off G#14 vel:74
junk: 10.902 | Cb:1 Misc | M? 0x61 0xbd
junk: 10.902 | Cb:7 Misc | M? 0x50 0x15
junk: 10.902 | Cb:11 Misc | M? 0x69 0xae
junk: 10.902 | Cb:8 Sysex Start [3B] |  0x84 0xd4 0x54
junk: 10.902 | Cb:3 Ch:8 PolyKey Press | After Touch Poly E19 pressure:191
junk: 10.902 | Cb:2 Ch:2 PolyKey Press | After Touch Poly F#14 pressure:250
junk: 10.902 | Cb:7 Ch:13 Channel Pressure | After Touch Channel 212
junk: 10.902 | Cb:10 Ch:9 PolyKey Press | After Touch Poly F#15 pressure:254
junk: 10.902 | Cb:13 Sysex Start [3B] |  0x54 0x18 0x97
junk: 10.902 | Cb:3 Sysex End [1B] | Sysex Cin Packet 0xcd
junk: 10.902 | Cb:11 Ch:11  | Note Off G#4 vel:182
junk: 10.902 | Cb:15 Ch:4 Channel Pressure | After Touch Channel 241
junk: 10.902 | Cb:15 Ch:8  | Note On E4 vel:228
junk: 10.902 | Cb:2 Misc | M? 0x3a 0x2b
junk: 10.902 | Cb:5 Misc | M? 0x09 0x15
I (10904) pd log: allocated TLS for thread: midi_usb_tx. 0x3fcd8bb4.
I (10904) pd midi usb OUT: USB OUT task started

#
# I unplug the USB Device here
#

buzz F 4 698Hz 100ms
hal:3
port:2
I (11364) : e1 : [pd usbh] USB TRANSFER FAILED - no device
e2 : [pd usbh [device]] submitTransferAndWait() failed
e3 : [pd midi usb IN] xfer IN task: DEV GONE

I (11374) pd midi usb IN: xferInTask_loop ended. wait for usb replug.
I (11374) pd_buzz: USB Device Removed Sound
buzz F 4 698Hz 100ms
E (11364) USBH: Device 1 gone
W (11394) pd usbh: [client task] DEV_GONE dev_hdl: 0x3deb85b0
W (11404) pd usbh: [close device] closing, dev_hdl: 0x3deb85b0
I (11404) pd usbh: [close device] unblocking usb transfer 3
I (11414) pd usbh: usb_host_interface_release(0x3deb84a0, device: 0x3deb85b0, bInterfaceNumber: 1
I (11424) pd usbh: interface fully released
I (11424) pd usbh: [close device] usb_host_device_close(client:0x3deb84a0,dev:0x3deb85b0)
I (11444) pd usbh: [close device] 0 devices still open
I (11404) pd usbh: [host task] usb_host_lib_handle_events()
I (11444) pd usbh: [host task] event: USB_HOST_LIB_EVENT_FLAGS - ALL_FREE
I (11454) pd usbh: [host task] usb_host_lib_handle_events()
I (11454) pd usbh: [host task] usb_host_lib_handle_events()
buzz C 4 523Hz 100ms
I (11594) pd usbh: [uninitialize] called
I (11594) pd usbh: [uninitialize] got mutex
I (11594) pd usbh: cancelAllTransfers()
I (11594) pd usbh: [uninitialize] Stopping xUsbClientTask...
I (11604) pd usbh: [uninitialize] usb_host_client_unblock(client:0x3deb84a0)
I (11734) pd usbh: [client task] vTaskDelete()
I (12134) xesp usb parse: Free config pool
I (12134) pd usbh: [openSingleDevice] called
I (12134) pd usbh: [openSingleDevice] all devices closed. continuing...
I (12154) pd usbh: [openSingleDevice] initializing usbh
I (12154) pd usbh: [init] initialize
hal:2
port:1
I (12614) pd usbh: [uninitialize] xUsbClientTask completed
I (12614) pd usbh: [uninitialize] 0 devices need closing
I (12614) pd usbh: closeAllDevices()
I (12624) pd usbh: closeAllDevices() complete
I (12624) pd usbh: [uninitialize] usb_host_client_deregister(client:0x3deb84a0)
I (12634) pd usbh: [uninitialize] Stopping xUsbHostTask...
I (12634) pd usbh: [uninitialize] usb_host_lib_unblock()
hal:4
port:0
hal:1
hal:1
hal:1
I (12774) pd usbh: [host task] event: USB_HOST_LIB_EVENT_FLAGS - NO_CLIENTS
I (12774) pd usbh: [host task] usb_host_device_free_all()
I (12784) pd usbh: [host task] usb_host_lib_handle_events()
hal:5
port:0
hal:4
port:0
hal:1
hal:1
I (12844) pd usbh: [host task] usb_host_lib_handle_events()
hal:1
hal:1
hal:1
I (12844) pd usbh: [host task] usb_host_lib_handle_events()
hal:1
hal:1
hal:1
I (12854) pd usbh: [host task] usb_host_lib_handle_events()
hal:1
hal:1
hal:1
I (12854) pd usbh: [host task] usb_host_lib_handle_events()
hal:1
hal:1
I (12874) pd usbh: [host task] usb_host_lib_handle_events()
hal:1
hal:1
hal:1
I (12874) pd usbh: [host task] usb_host_lib_handle_events()
hal:1
hal:1
hal:1
I (12884) pd usbh: [host task] usb_host_lib_handle_events()
hal:1
hal:1
hal:1
I (12884) pd usbh: [host task] usb_host_lib_handle_events()
hal:1
hal:1
hal:1
I (12894) pd usbh: [host task] usb_host_lib_handle_events()
hal:1
hal:1
hal:1
I (12904) pd usbh: [host task] usb_host_lib_handle_events()
hal:1
hal:1
hal:1
I (12914) pd usbh: [host task] usb_host_lib_handle_events()
hal:1
hal:1
hal:1
I (12924) pd usbh: [host task] usb_host_lib_handle_events()
hal:1
hal:1
hal:1
I (12934) pd usbh: [host task] usb_host_lib_handle_events()
I (12944) pd usbh: [host task] usb_host_lib_handle_events()
I (12944) pd usbh: [host task] usb_host_lib_handle_events()
I (13064) pd usbh: [host task] vTaskDelete()
I (13654) pd usbh: [uninitialize] uxUsbHostTask completed
I (13654) pd usbh: [uninitialize] usb_host_uninstall()
process_pending_flags 0
lib_event_flags 0
flags.val 0
hal:3
port:2
ESP_ERROR_CHECK failed: esp_err_t 0x103Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.

Core  1 register dump:
PC      : 0x42087639  PS      : 0x00060f33  A0      : 0x8208664d  A1      : 0x3fca1d80  
0x42087639: root_port_callback at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/usb/hub.c:703

A2      : 0x3fcd4bec  A3      : 0x00000002  A4      : 0x00000000  A5      : 0x00000001  
A6      : 0x00060023  A7      : 0x00060022  A8      : 0x3fcac374  A9      : 0x00000000  
A10     : 0x00000001  A11     : 0xa23311f5  A12     : 0xa23311f5  A13     : 0x3fca79ac  
A14     : 0x00060f23  A15     : 0x00060f22  SAR     : 0x00000004  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  

Backtrace:0x42087636:0x3fca1d800x4208664a:0x3fca1db0 0x40378fc1:0x3fca1de0 0x420c50cc:0x3fcf5820 0x42006349:0x3fcf5850 0x403853eb:0x3fcf5880 0x40388252:0x3fcf58b0 
0x42087636: root_port_callback at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/usb/hub.c:703

0x4208664a: intr_hdlr_main at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/usb/hcd.c:956

0x40378fc1: _xt_medint2 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1200

0x420c50cc: cpu_ll_waiti at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/hal/esp32s3/include/hal/cpu_ll.h:182
 (inlined by) esp_pm_impl_waiti at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/esp_pm/pm_impl.c:837

0x42006349: esp_vApplicationIdleHook at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/esp_system/freertos_hooks.c:63

0x403853eb: prvIdleTask at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/tasks.c:3973 (discriminator 1)

0x40388252: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/port/xtensa/port.c:131

ELF file SHA256: 6ba9c090eb1d360d

I (10963) esp_core_dump_flash: Save core dump to flash...
I (10969) esp_core_dump_flash: Erase flash 53248 bytes @ 0x10000
I (11705) esp_core_dump_flash: Write end offset 0xc4a4, check sum length 4
I (11705) esp_core_dump_flash: Core dump has been saved to flash.
CPU halted.

[chipweinberger]

And here are the full logs

``` /Volumes/User/MBP-Google-Drive/jamcorder/firmware/.espressif/python_env/idf4.4_py3.9_env/bin/python % charlesweinberger@Chips-Macbook-Pro-2 jamcorder_app % /Volumes/User/MBP-Google-Drive/jamcorder/firmwar e/.espressif/python_env/idf4.4_py3.9_env/bin/python /Volumes/User/MBP-Google-Drive/jamcorder/firmware/ esp-idf/tools/idf.py -p /dev/cu.SLAB_USBtoUART monitor Executing action: monitor Running idf_monitor in directory /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_app Executing "/Volumes/User/MBP-Google-Drive/jamcorder/firmware/.espressif/python_env/idf4.4_py3.9_env/bin/python /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/tools/idf_monitor.py -p /dev/cu.SLAB_USBtoUART -b 115200 --toolchain-prefix xtensa-esp32s3-elf- --target esp32s3 /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_app/build/jamcorderApp.elf -m '/Volumes/User/MBP-Google-Drive/jamcorder/firmware/.espressif/python_env/idf4.4_py3.9_env/bin/python' '/Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/tools/idf.py' '-p' '/dev/cu.SLAB_USBtoUART'"... --- idf_monitor on /dev/cu.SLAB_USBtoUART 115200 --- --- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H --- ESP-ROM:esp32s3-20210327 Build:Mar 27 2021 rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT) SPIWP:0xee mode:DIO, clock div:1 load:0x3fcd0268,len:0x21dc load:0x403b6000,len:0x13b4 load:0x403ba000,len:0x2e94 entry 0x403b6358 W (24) boot.esp32s3: eFuse virtual mode is enabled. If Secure boot or Flash encryption is enabled then it does not provide any security. FOR TESTING ONLY! W (29) efuse: Loading virtual efuse blocks from real efuses I (47) boot: ESP-IDF v4.4.2-1-gce1fde4b3b-dirty 2nd stage bootloader I (47) boot: compile time 01:02:45 I (47) boot: chip revision: 0 I (51) boot.esp32s3: Boot SPI Speed : 80MHz I (56) boot.esp32s3: SPI Mode : DIO I (60) boot.esp32s3: SPI Flash Size : 8MB I (65) boot: Enabling RNG early entropy source... I (70) boot: Partition Table: I (74) boot: ## Label Usage Type ST Offset Length I (81) boot: 0 otadata OTA data 01 00 0000d000 00002000 I (89) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (96) boot: 2 coredump Unknown data 01 03 00010000 00010000 I (104) boot: 3 nvs_key NVS keys 01 04 00020000 00001000 I (111) boot: 4 nvs WiFi data 01 02 00021000 00060000 I (119) boot: 5 jCoredumpExtra Unknown data 01 06 00081000 00008000 I (126) boot: 6 jBootArgs Unknown data 01 06 00089000 00004000 I (134) boot: 7 jBootVer Unknown data 01 06 0008d000 00004000 I (141) boot: 8 jDevCmds Unknown data 01 06 00091000 00004000 I (149) boot: 9 jDeviceTree Unknown data 01 06 00095000 00008000 I (156) boot: 10 jJfuArgs Unknown data 01 06 0009d000 00008000 I (164) boot: 11 jJfuApp OTA app 00 11 000b0000 00226000 I (172) boot: 12 jExtra1 Unknown data 01 06 002d6000 00020000 I (179) boot: 13 jExtra2 Unknown data 01 06 002f6000 00008000 I (187) boot: 14 jExtra3 Unknown data 01 06 002fe000 00002000 I (194) boot: 15 jJamArgs Unknown data 01 06 00300000 00004000 I (202) boot: 16 jJamApp OTA app 00 10 00310000 004f0000 I (209) boot: End of partition table I (214) boot: No factory image, trying OTA 0 I (219) boot: bootloader_utility_get_selected_boot_partition: 0 I (225) boot ver: read json I (229) boot: found: jBootVer, offset:0x8d000 size:16384 I (235) boot ver: read {"jBootVer":"0.2","compileDate":"Sep 1 2022","compileTime":"01:02:47","ESP-IDF":"v4.4.2-1-gce1fde4b3b-dirty"} I (247) boot ver: jBootVer already written I (252) boot: Clearing ota_data Partition... I (257) boot_comm: ## Label Usage Offset Length Cleaned I (354) boot_comm: 0 otadata data 0000d000 00002000 [yes] I (354) boot_comm: 1 phy_init data 0000f000 00001000 [no] I (357) boot_comm: 2 coredump data 00010000 00010000 [no] I (364) boot_comm: 3 nvs_key data 00020000 00001000 [no] I (370) boot_comm: 4 nvs data 00021000 00060000 [no] I (377) boot_comm: 5 jCoredumpExtra data 00081000 00008000 [no] I (384) boot_comm: 6 jBootArgs data 00089000 00004000 [no] I (391) boot_comm: 7 jBootVer data 0008d000 00004000 [no] I (398) boot_comm: 8 jDevCmds data 00091000 00004000 [no] I (405) boot_comm: 9 jDeviceTree data 00095000 00008000 [no] I (412) boot_comm: 10 jJfuArgs data 0009d000 00008000 [no] I (419) boot_comm: 12 jExtra1 data 002d6000 00020000 [no] I (426) boot_comm: 13 jExtra2 data 002f6000 00008000 [no] I (433) boot_comm: 14 jExtra3 data 002fe000 00002000 [no] I (440) boot_comm: 15 jJamArgs data 00300000 00004000 [no] I (447) boot: Note: Hold User Button down during boot to see boot menu! I (454) boot: Waiting 1.5 seconds for user to press button... I (1954) boot: GPIO not held I (1954) boot: GPIO hold time: 0 I (1954) esp_image: segment 0: paddr=00310020 vaddr=3c160020 size=bd7c8h (776136) map I (2098) esp_image: segment 1: paddr=003cd7f0 vaddr=3fca0580 size=02828h ( 10280) load I (2100) esp_image: segment 2: paddr=003d0020 vaddr=42000020 size=15c26ch (1426028) map I (2359) esp_image: segment 3: paddr=0052c294 vaddr=3fca2da8 size=04bech ( 19436) load I (2364) esp_image: segment 4: paddr=00530e88 vaddr=40374000 size=1c574h (116084) load I (2391) esp_image: segment 5: paddr=0054d404 vaddr=50000000 size=00010h ( 16) load I (2402) boot: Loaded app from partition at offset 0x310000 I (2453) boot: Set actual ota_seq=1 in otadata[0] I (2453) boot: Disabling RNG early entropy source... I (2465) spiram: Found 16MBit SPI RAM device I (2465) spiram: SPI RAM mode: sram 40m I (2465) spiram: PSRAM initialized, cache is in normal (1-core) mode. I (2470) cpu_start: Pro cpu up. I (2474) cpu_start: Starting app cpu, entry point is 0x40375844 0x40375844: call_start_cpu1 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/esp_system/port/cpu_start.c:160 I (0) cpu_start: App cpu up. I (2899) spiram: SPI SRAM memory test OK I (2911) cpu_start: Pro cpu start user code I (2911) cpu_start: cpu freq: 240000000 I (2911) cpu_start: Application information: I (2914) cpu_start: Project name: jamcorderApp I (2919) cpu_start: App version: 0.5 I (2924) cpu_start: Compile time: Sep 1 2022 01:02:58 I (2930) cpu_start: ELF file SHA256: 6ba9c090eb1d360d... I (2936) cpu_start: ESP-IDF: v4.4.2-1-gce1fde4b3b-dirty I (2943) heap_init: Initializing. RAM available for dynamic allocation: I (2950) heap_init: At 3FCB3758 len 0002C8A8 (178 KiB): D/IRAM I (2957) heap_init: At 3FCE0000 len 0000EE34 (59 KiB): STACK/DRAM I (2963) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM I (2970) heap_init: At 600FE000 len 00002000 (8 KiB): RTCRAM I (2976) spiram: Adding pool of 2048K of external SPI memory to heap allocator I (3252) spi_flash: detected chip: generic I (3252) spi_flash: flash io: dio W (3253) cpu_start: eFuse virtual mode is enabled. If Secure boot or Flash encryption is enabled then it does not provide any security. FOR TESTING ONLY! W (3265) efuse: Loading virtual efuse blocks from real efuses I (3271) sleep: Configure to isolate all GPIO pins in sleep state I (3278) sleep: Enable automatic switching of GPIO sleep configuration I (3285) esp_core_dump_flash: Init core dump to flash I (3291) esp_core_dump_flash: Found partition 'coredump' @ 10000 65536 bytes I (3298) coexist: coexist rom version e7ae62f I (3304) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (3314) spiram: Reserving pool of 32K of internal memory for DMA/internal allocations I (3324) pd main: app_main() called I (3334) pd main: LED - set solid green I (3334) gpio: GPIO[15]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 I (3384) pd log: replace logging function with 0x4202466c 0x4202466c: _pd_log_vprintf(char const*, __va_list_tag) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/logs/pd_log.cpp:765 I (3384) pd log: allocated TLS for thread: main. 0x3fce0e74. pd log: timeout 7: I (3384) pd sd card: configuring GPIO SD Card Detect pd log: timeout 7: I (3584) gpio: GPIO[21]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 I (3384) pd developer: init json read: {"developerMode":0,"cmds":[]} I (3784) pd developer: read json success I (3794) pd developer: developerMode: off I (3794) pd developer: 0 cmds found I (3804) pd developer: init success __ _ \ \ __ _ _ __ ___ ___ ___ _ __ __| | ___ _ __ \ \/ _` | '_ ` _ \ / __/ _ \| '__/ _` |/ _ \ '__| /\_/ / (_| | | | | | | (_| (_) | | | (_| | __/ | \___/ \__,_|_| |_| |_|\___\___/|_| \__,_|\___|_| I (3824) pd main: Running Partition: jJamApp size: 5056KB I (3834) pd main: Bootloader: {"jBootVer":"0.2","compileDate":"Sep 1 2022","compileTime":"01:02:47","ESP-IDF":"v4.4.2-1-gce1fde4b3b-dirty"} I (3844) pd_buzz: xTaskCreate buzz_async_task I (3854) pd log: allocated TLS for thread: buzz_async. 0x3fce0f2c. I (3854) pd_buzz: buzz async task started I (3854) pd led: xTaskCreate led_task I (3864) pd led ux: booting I (3864) pd log: allocated TLS for thread: led_task. 0x3fce0fc0. I (3864) pd led: led task started LED: blink. group:0 r:0 g:255 b:0 I (3884) pd main: calling gpio_install_isr_service() I (3894) pd user button: xTaskCreate user_button_task I (3894) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 I (3904) fuse: fusesSchemaMajorVer 0 I (3914) fuse: fusesSchemaMinorVer 0 I (3914) fuse: manufactureYear 0 I (3914) fuse: manufactureMonth 0 I (3924) fuse: manufactureDay 0 I (3924) fuse: serialNumber 0 I (3934) fuse: randomSerialNumber 0 I (3934) fuse: isBetaDevice 0 I (3934) fuse: isConsumerDevice 0 I (3944) fuse: isUsbJtagDisabled 0 I (3944) fuse: isPadJtagDisabled 0 I (3954) fuse: modelName Jamcorder I (3954) fuse: modelNumber JMX0000 I (3954) fuse: modelRev 0 I (3964) fuse: modelFuse 0 I (3964) pd nvs: init I (4174) pd nvs utils: logging all entries: I (4174) pd nvs utils: MidiRecordSysex : u8 : 1 I (4174) pd nvs utils: MidiSilenceSkip : u8 : 1 I (4174) pd nvs utils: DeviceName : string : My Jamcorder I (4184) pd nvs utils: PerformerName : string : Default Performer I (4194) pd nvs utils: DeviceId : string : och5cl2fotoa I (4194) pd nvs utils: PerformerId : string : ybuonndsu47sd4q51r I (4204) pd nvs utils: WifiHomePass : string : runninghorse I (4214) pd nvs utils: WifiHomeSSID : string : junior_2.4ghz I (4214) pd nvs utils: BootNewHomeCred : u8 : 0 I (4224) pd nvs utils: TimeUtcOffset : i16 : -420 I (4234) pd nvs utils: TimeDls : blob : 144bytes 0x7767633fcb6f60... I (4234) pd nvs utils: DiscvUsrIntrctd : u32 : 1 I (4244) pd nvs utils: LifeNotes : u64 : 30 I (4244) pd nvs utils: LifeMillis : u64 : 24800 I (4254) pd nvs utils: CmdOctave : u8 : 7 I (4254) pd nvs utils: CmdSafeNote : i8 : -1 I (4264) pd nvs utils: MidiAssetCount : u64 : 5 I (4264) pd nvs utils: CmdDisableAll : u8 : 0 I (4274) pd nvs utils: CmdDisablePlay : u8 : 0 I (4274) pd nvs utils: LifeNotesPlay : u64 : 31 I (4284) pd nvs utils: LifeMillisPlay : u64 : 12217 I (4284) pd nvs utils: LifeNotesRec : u64 : 31 I (4294) pd nvs utils: LifeMillisRec : u64 : 8000 I (4304) pd nvs utils: BootCount : u32 : 227 I (4304) pd nvs utils: ClockProgCount : u64 : 208 I (4314) pd nvs utils: ClockStartTime : u64 : 1662166085 I (4314) pd nvs utils: MidiBookmkCount : I (4324) pd nvs utils: TimeSntpDisable : I (4324) pd nvs utils: BootDiscovery : I (4334) pd nvs utils: BootHomeWifiErr : I (4334) pd nvs utils: VerboseTagNums : I (4354) pd_buzz: Jamcorder Boot Sound buzz C 4 523Hz 120ms buzz D 4 587Hz 120ms buzz E 4 659Hz 120ms buzz G 4 783Hz 120ms buzz A 5 880Hz 120ms buzz C 5 1046Hz 120ms I (5074) pd main: isConsumerDevice: no LED: dazzle cmy I (5824) pd main: isDeveloperDevice: yes I (5824) pd_buzz: buzz once sound buzz A 4 440Hz 100ms LED: dazzle cmy I (6674) pd boot args jam: one time read json read: {} (Sentinel Not Found) I (6674) pd partition utils: Erase Partition: jJamArgs I (6674) pd partition utils: 16384 bytes I (6684) pd partition utils: partition erased. 0 sectors erased. I (6684) pd time: init I (6694) pd localtime: settimeofday updated 1662141030 I (6694) pd time: [init] current unixtime: 2022-9-3 00:50:30 weekday: 7 year_offset: 0 I (6704) pd time: Time Source: sntp I (6714) pd localtime: Initialized I (6714) pd main: UTC Offset: -420 I (6714) pd coredump extra: pd_has_new_coredump() called I (6876) esp_core_dump_flash: Core dump data checksum is correct I (6894) pd coredump extra: No new coredump found. hashes are equal. I (6894) pd shared file: initialize I (6894) pd sd card: Init I (6894) pd sd card: (SD card detect) SD card detected at boot. I (6904) pd sd card: opening SD card (SDMMC) I (6904) pd sd card: Mounting SD card. format_if_mount_failed? NO I (6914) gpio: GPIO[11]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 I (6924) gpio: GPIO[12]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 I (6934) gpio: GPIO[10]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 I (6944) gpio: GPIO[9]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 I (6954) gpio: GPIO[14]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 I (6954) gpio: GPIO[13]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 I (7004) gpio: GPIO[13]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 I (7014) pd sd card: host: Sd Host: flags: 23 slot: 1 max freq: 20000 khz io voltage: 3.300v command timeout: 0ms I (7014) pd sd card: SD card successfully mounted. I (7024) pd sd card: Card: SD Type: SDHC/SDXC Speed: 20 MHz Size: 15200MB I (7034) pd main: on filesystem MOUNTED called I (7034) pd log: Setting Error Output File: /sd/JAMC/other/device-och5cl/logs/jamcorderErrors.txt I (7054) pd file utils: fopen 0x3de00d30, /sd/JAMC/other/device-och5cl/logs/jamcorderErrors.txt I (7054) pd CR2032: eFuse Vref: No I (7064) pd CR2032: eFuse Default Vref: No I (7064) pd CR2032: eFuse Two Point: No I (7064) pd CR2032: eFuse Two Point Fit: YES I (7074) pd CR2032: gpio: 2 adc: 1 channel: 1 I (7074) pd CR2032: Characterized with eFuse TP Fit I (7094) pd CR2032: Raw: 3514 Calibrated: 3248mV I (7094) pd main: Voltage CR2032: 3248mV ~100% I (7104) pd api init: pd_api_init() called I (7104) pd api: allocating API list I (7104) pd api: register [0] /webapp I (7114) pd api: register [1] /webapp/* I (7114) pd api: register [2] /sd/?* I (7124) pd api: register [3] /api/device-state I (7124) pd api: register [4] /api/time/get I (7134) pd api: register [5] /api/time/set I (7134) pd api: register [6] /api/time/sntp-disable I (7144) pd api: register [7] /api/time/sntp-enable I (7144) pd api: register [8] /api/time/guess-time-from-sd-card I (7154) pd api: register [9] /api/device-name/get I (7154) pd api: register [10] /api/device-name/rename I (7164) pd api: register [11] /api/performer-name/get I (7174) pd api: register [12] /api/performer-name/rename I (7174) pd api: register [13] /api/wifi/info I (7184) pd api: register [14] /api/wifi/set-credentials I (7184) pd api: register [15] /api/wifi/clear-credentials I (7194) pd api: register [16] /api/wifi/scan I (7194) pd api: register [17] /api/bluetooth/state I (7204) pd api: register [18] /api/bluetooth/detailed-state I (7214) pd api: register [19] /ble-test I (7214) pd api: register [20] /api/usb/state I (7214) pd api: register [21] /api/usb/descriptors I (7224) pd api: register [22] /api/sd/?* I (7234) pd api: register [23] /api/sd-card/format-if-needed I (7234) pd api: register [24] /api/sd-card/info I (7244) pd api: register [25] /api/sd-card/free-bytes I (7244) pd api: register [26] /api/sd-card/print-details I (7254) pd api: register [27] /api/files/list-files I (7254) pd api: register [28] /api/files/list-files-detailed I (7264) pd api: register [29] /api/files/download-file I (7274) pd api: register [30] /api/files/download-file-at-offset I (7274) pd api: register [31] /api/files/upload-file/* I (7284) pd api: register [32] /api/piano/state I (7284) pd api: register [33] /api/library/download-most-recent-asset I (7294) pd api: register [34] /api/library/list-recent-assets I (7304) pd api: register [35] /api/asset/next-header I (7304) pd api: register [36] /api/asset/next-details I (7314) pd api: register [37] /api/asset/eof-summary I (7324) pd api: register [38] /api/midi-cmd/player/play I (7324) pd api: register [39] /api/midi-cmd/player/pause I (7334) pd api: register [40] /api/midi-cmd/player/exit I (7334) pd api: register [41] /api/midi-cmd/player/rewind I (7344) pd api: register [42] /api/midi-cmd/player/fast-forward I (7354) pd api: register [43] /api/midi-cmd/player/seek-forward I (7354) pd api: register [44] /api/midi-cmd/player/seek-backwards I (7364) pd api: register [45] /api/midi-cmd/bookmark I (7374) pd api: register [46] /api/midi-cmd/settings I (7374) pd api: register [47] /api/midi-cmd/set-settings I (7384) pd api: register [48] /api/midi-tests/triad-out I (7384) pd api: register [49] /api/midi-tests/triad-in I (7394) pd api: register [50] /api/midi-tests/complex-in I (7404) pd api: register [51] /api/midi-tests/complex-out I (7404) pd api: register [52] /api/midi-io/msg-counts I (7414) pd api: register [53] /api/midi-io/active-converters I (7414) pd api: register [54] /extensions/* I (7424) pd api: register [55] /api/extensions/list I (7424) pd api: register [56] /api/extensions/upload-install-html/* I (7434) pd api: register [57] /api/extensions/upload-install-tar/* I (7444) pd api: register [58] /api/extensions/uninstall I (7444) pd api: register [59] /api/peripherals/adc-details I (7454) pd api: register [60] /api/core-dump/download I (7464) pd api: register [61] /api/core-dump/info I (7464) pd api: register [62] /api/nvs/list-all I (7474) pd api: register [63] /api/nvs/set I (7474) pd api: register [64] /api/test/force-system-crash I (7484) pd api: register [65] /api/system/enter-discovery-mode I (7484) pd api: register [66] /api/system/system-info I (7494) pd api: register [67] /api/system/freertos-tasks I (7504) pd api: register [68] /api/system/print-alloc-stats I (7504) pd api: register [69] /api/system/heap-usage I (7514) pd api: register [70] /api/system/check-heap-integrity I (7524) pd api: register [71] /api/system/partition-table I (7524) pd api: register [72] /api/system/reboot I (7534) pd api: register [73] /api/system/factory-reset I (7534) pd api: register [74] /api/system/heap-trace-start-all I (7544) pd api: register [75] /api/system/heap-trace-start-leaks I (7554) pd api: register [76] /api/system/heap-trace-stop I (7554) pd api: register [77] /api/system/is-alive I (7564) pd api: register [78] /api/issues/current I (7564) pd api: register [79] /api/issues/history I (7574) pd api: register [80] /api/issues/clear-current I (7584) pd api: register [81] /api/developer/state I (7584) pd api: register [82] /api/developer/developer-mode-enable I (7594) pd api: register [83] /api/developer/developer-mode-disable I (7594) pd api: register [84] /api/developer/list-cmds I (7604) pd api: register [85] /api/developer/cmd-set I (7614) pd api: register [86] /api/developer/cmd-unset I (7614) pd api: register [87] /api/developer/reset-all I (7624) pd api: register [88] /api/ota/upload-firmware/* I (7624) pd api: register [89] /api/ota/download-firmware/* I (7634) pd api: register [90] /api/hardware-info/get I (7644) pd api: register [91] /api/hardware-info/set I (7644) pd api: register [92] /api/hardware-info/efuses I (7654) pd api: register [93] /api/hardware-info/efuses-raw I (7654) pd api: register [94] /logs I (7664) pd api: register [95] /api/logs/websocket I (7664) pd api: register [96] /api/logs/recent-logs I (7674) pd api: register [97] /api/logs/recent-errors I (7684) pd api: register [98] /api/logs/recent-warnings I (7684) pd api: register [99] /api/logs/download-log-file I (7694) pd api: register [100] /api/logs/download-top-of-log-file I (7694) pd api: register [101] /api/logs/download-error-file I (7704) pd api: register [102] /api/logs/download-top-of-error-file I (7714) pd api: register [103] /jfu I (7714) pd api: register [104] /api/jfu/reboot-into-jfu I (7724) pd api: register [105] /api/jfu/enable-sd-card-boot-arg I (7724) pd api: register [106] /internal I (7734) pd api: register [107] / I (7734) pd api: register [108] /favicon.ico I (7744) pd api: register [109] /api/verbose/list I (7744) pd api: register [110] /api/verbose/state I (7754) pd api: register [111] /api/verbose/enable I (7754) pd api: register [112] /api/verbose/disable I (7764) pd api: register [113] /api/verbose/disable-all I (7774) pd api: register [114] /api/verbose/persist I (7774) pd api: register [115] /api/verbose/unpersist I (7784) pd api init: API Count 116 I (7784) pd wifi: Entering Home Wifi Mode I (7794) pd wifi: wifi_start_internal(homeWifi) I (7794) pd wifi: esp_netif_init() I (7804) pd wifi: esp_event_loop_create_default() I (7804) pd wifi: esp_netif_create_default_wifi_sta() I (7814) pd wifi: esp_wifi_init() I (7814) pp: pp rom version: e7ae62f I (7824) net80211: net80211 rom version: e7ae62f I (7854) wifi_init: rx ba win: 6 I (7854) wifi_init: tcpip mbox: 32 I (7854) wifi_init: udp mbox: 6 I (7854) wifi_init: tcp mbox: 6 I (7854) wifi_init: tcp tx win: 6500 I (7864) wifi_init: tcp rx win: 6500 I (7864) wifi_init: tcp mss: 1440 I (7874) wifi_init: WiFi/LWIP prefer SPIRAM I (7874) pd wifi: esp_event_handler_instance_register(ESP_EVENT_ANY_ID) I (7884) pd wifi: esp_event_handler_instance_register(IP_EVENT_STA_GOT_IP) I (7894) pd wifi: esp_wifi_set_mode(WIFI_MODE_STA) I (7894) pd wifi: switching to 'Connect To Home Wifi' mode I (7904) pd wifi: ssid:junior_2.4ghz password:runninghorse I (7904) pd wifi: esp_wifi_set_config(WIFI_IF_STA) I (7914) pd wifi: esp_wifi_start() I (7914) pd log: allocated TLS for thread: wifi. 0x3fce6a7c. I (7914) phy_init: phy_version 503,13653eb,Jun 1 2022,17:47:08 I (7964) pd mdns: mdns_init() I (7964) pd log: allocated TLS for thread: sys_evt. 0x3fce6cb0. I (7964) pd wifi: Wifi Event: STA Mode - Start I (7974) pd mdns: mdns_hostname_set(jamcorder) I (7974) pd mdns: mdns_instance_name_set(My Jamcorder) I (7984) pd mdns: netbiosns_init() I (7984) pd mdns: netbiosns_set_name(jamcorder) I (7994) pd http api: pd_http_api_init() called I (7994) pd http api: httpd_start() I (8004) keep alive: pd_ws_keepalive_init() I (8014) pd http logs: pd_http_logs_ws_init() I (8014) pd http api: registering 116 uris I (8024) pd wifi: Wifi Event: STA Mode - Connected I (8044) pd console api: init I (8044) pd console api: registering 116 uris I (8074) pd bt midi: init I (8074) pd bt midi in: init I (8074) pd bt midi out: init I (8074) pd bt midi out: xTaskCreate midi_bt_tx_task I (8094) pd bt midi out: allocate msg queue: 44000 bytes I (8104) pd bt api: init I (8104) pd log: allocated TLS for thread: midi_bt_tx. 0x3fcc1bb8. I (8104) pd bt midi out: Bluetooth OUT task started I (8104) pd bt api: xTaskCreate btApiTask I (8124) pd ble: init I (8124) pd log: allocated TLS for thread: btApiTask. 0x3fcc3d74. I (8124) pd bt api: btApiTask started W (8124) BT_INIT: esp_bt_controller_mem_release not implemented, return OK I (8144) BT_INIT: BT controller compile version [05195c9] I (8144) pd log: allocated TLS for thread: btController. 0x3fcca86c. I (8144) BT_INIT: Bluetooth MAC: 00:63:68:35:63:6e I (8174) pd log: allocated TLS for thread: ble. 0x3fcceac4. I (8174) pd ble: Start Nimble Port Run I (8184) pd ble: GATT registered service: I (8194) pd ble: uuid: 0x1800 I (8194) pd ble: svc: GAP Svc I (8194) pd ble: handle: 1 I (8194) pd ble: GATT registered characteristic: I (8204) pd ble: uuid: 0x2a00 I (8204) pd ble: chr: GAP Device Name I (8204) pd ble: defHandle: 2 I (8224) pd ble: valHandle: 3 I (8224) pd ble: GATT registered characteristic: I (8224) pd ble: uuid: 0x2a01 I (8224) pd ble: chr: GAP Appearance I (8234) pd ble: defHandle: 4 I (8234) pd ble: valHandle: 5 I (8234) pd ble: GATT registered service: I (8244) pd ble: uuid: 0x1801 I (8254) pd ble: svc: GATT Svc I (8254) pd ble: handle: 6 I (8254) pd ble: GATT registered characteristic: I (8264) pd ble: uuid: 0x2a05 I (8264) pd ble: chr: GATT Service Changed I (8264) pd ble: defHandle: 7 I (8274) pd ble: valHandle: 8 I (8274) pd ble: GATT registered service: I (8284) pd ble: uuid: 02aa0001-4202-649d-ec11-dfdb58e9372d I (8294) pd ble: svc: Jmx SPP Api Svc I (8294) pd ble: handle: 10 I (8294) pd ble: GATT registered characteristic: I (8304) pd ble: uuid: 02aa0002-4202-649d-ec11-dfdb58e9372d I (8304) pd ble: chr: Jmx SPP Tx I (8324) pd ble: defHandle: 11 I (8324) pd ble: valHandle: 12 I (8324) pd ble: GATT registered characteristic: I (8324) pd ble: uuid: 02aa0003-4202-649d-ec11-dfdb58e9372d I (8334) pd ble: chr: Jmx SPP Rx I (8334) pd ble: defHandle: 14 I (8344) pd ble: valHandle: 15 I (8344) pd ble: GATT registered service: I (8354) pd ble: uuid: 02aa0001-4203-649d-ec11-dfdb58e9372d I (8364) pd ble: svc: Jmx Midi File Stream Svc I (8364) pd ble: handle: 16 I (8364) pd ble: GATT registered characteristic: I (8374) pd ble: uuid: 02aa0002-4203-649d-ec11-dfdb58e9372d I (8374) pd ble: chr: Jmx MFS I (8374) pd ble: defHandle: 17 I (8394) pd ble: valHandle: 18 I (8394) pd ble: GATT registered service: I (8394) pd ble: uuid: 03b80e5a-ede8-4b33-a751-6ce34ec4c700 I (8404) pd ble: svc: Ble Midi Svc I (8404) pd ble: handle: 20 I (8404) pd ble: GATT registered characteristic: I (8414) pd ble: uuid: 7772e5db-3868-4112-a1a9-f2669d106bf3 I (8424) pd ble: chr: Ble Midi I (8424) pd ble: defHandle: 21 I (8434) pd ble: valHandle: 22 I (8434) pd ble: on_ble_sync_handler() called I (8444) pd ble: ownAddrType: Public I (8444) pd ble: Device Address: 00:63:68:35:63:6e I (8454) pd ble: ***** start advertising ***** pd log: timeout 7: I (8184) pd ble: Set BLE TX Power Level: +6dbm I (8454) pd ble: Set BLE Advertise Power Level: +6bm I (8474) pd midi pipeline: allocate msg queue: 216000 bytes I (8524) pd midi pipeline: xTaskCreate midi_pipeline_task I (8534) pd uart midi: init I (8534) pd log: allocated TLS for thread: midi_pipeline. 0x3fcd05e4. I (8534) pd midi pipeline: midi pipeline task started I (8534) uart: queue free spaces: 100 I (8544) pd uart midi in: init I (8554) pd uart midi in: xTaskCreate midi_uart_rx_task I (8564) pd uart midi out: init I (8564) pd log: allocated TLS for thread: midi_uart_rx. 0x3fcd21f4. I (8564) pd uart midi in: rx task loop I (8564) pd uart midi out: xTaskCreate midi_uart_tx_task I (8574) pd uart midi out: allocate msg queue: 44000 bytes I (8594) pd usb c: Advertising as DEVICE I (8594) pd log: allocated TLS for thread: midi_uart_tx. 0x3fcd33b0. I (8594) pd uart midi out: UART OUT task started I (8604) pd usb c: disabling Vcc output I (8614) gpio: GPIO[35]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 I (8624) pd usb c: disabling Rp pullup resistor I (8624) gpio: GPIO[48]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 I (8644) pd usb c: enabling Rd pulldown resistor I (8644) gpio: GPIO[47]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 I (8654) pd usb c: gpio: 1 adc: 1 channel: 0 I (8654) pd usb c: Characterized with eFuse TP Fit I (8674) pd usb c: Usb CC Raw: 0 Calibrated: 0mV I (8674) pd usb c: Is PC Connected: Usb Host - Not Connected I (8674) pd usb c: Advertising as HOST I (8684) pd usb c: disabling Vcc output I (8694) gpio: GPIO[35]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 I (8704) pd usb c: disabling Rd pulldown resistor I (8704) gpio: GPIO[47]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 I (8714) pd usb c: enabling Rp pullup resistor I (8714) gpio: GPIO[48]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 I (8734) pd usb c: Usb CC Raw: 431 Calibrated: 369mV I (8744) pd usb c: Is Usb Device Connected: Usb Device - Connected I (8744) pd usb c: enabling Vcc output I (8754) gpio: GPIO[35]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 I (8754) pd midi usb: init I (8764) pd midi usb: xTaskCreate midi_usb_open_loop I (8764) pd main: Waiting 1.5 secs... I (8764) pd log: allocated TLS for thread: midiUsbhOpen. 0x3fcd45e0. I (8764) pd usbh: oneTimeInit() I (8784) pd usbh: [oneTimeInit] create xUsbhInitializeMutex I (8794) pd usbh: [oneTimeInit] create xOpenedDeviceHandlesMutex I (8794) pd usbh: [oneTimeInit] create queue xDeviceConnectedEvents I (8804) esp_netif_handlers: sta ip: 192.168.0.128, mask: 255.255.255.0, gw: 192.168.0.1 I (8814) pd wifi: IP Event: Station Mode - Got IP I (8824) pd wifi: got ip: 192.168.0.128 I (8824) pd led ux: home wifi connected I (8824) pd_sntp: Starting SNTP I (8834) pd mdns: mdns_delegate_hostname_add(192.168.0.128, jamcorder-och5cl) I (8844) pd mdns: success I (9294) pd log: allocated TLS for thread: tiT. 0x3fcd4a20. I (9294) pd_sntp: SNTP sec 3871155033 frac 2340370594 I (9304) pd_sntp: current unixtime: I (9314) pd_sntp: Time Drift of 0 minutes, -1 seconds corrected. I (9314) pd time: setting time 1662166233, sntp I (9314) pd time: set_DS1302_year_offset: 0 I (9334) pd time: 2022-9-3 00:50:33 weekday: 7 year_offset: 0 I (9334) pd time: unixtime: 1662166233 I (9334) pd localtime: settimeofday updated 1662141033 I (9344) pd nvs: incremented clock prog count to 209 I (9364) pd nvs: set Clock Start Time: 1662166233 I (9804) pd usbh: [openSingleDevice] called I (9804) pd usbh: [openSingleDevice] all devices closed. continuing... I (9804) pd usbh: [openSingleDevice] initializing usbh I (9824) pd usbh: [init] initialize I (9824) pd usbh: [init] got mutex I (9824) pd usbh: [init] xSemaphoreCreateRecursiveMutex() xClaimedInterfacesMutex I (9834) pd usbh: [init] usb_host_install() hal:2 port:1 I (9864) pd usbh: [init] xTaskCreate usb_host I (9864) pd usbh: [init] xSemaphoreCreateCounting() for transfer pool I (9864) pd log: allocated TLS for thread: usb_host. 0x3fcd4d44. I (9864) pd usbh: [init] xSemaphoreCreateMutex() transfer pool mutex I (9864) pd usbh: [host task] started... I (9884) pd usbh: [init] usb_host_transfer_alloc(buf: 264, isoc: 0, ...) I (9894) pd usbh: [host task] usb_host_lib_handle_events() I (9894) pd usbh: [init] usb_host_transfer_alloc(buf: 264, isoc: 0, ...) I (9904) pd usbh: [init] usb_host_transfer_alloc(buf: 264, isoc: 0, ...) I (9924) pd usbh: [init] usb_host_transfer_alloc(buf: 264, isoc: 0, ...) I (9924) pd usbh: [init] usb_host_client_register(...) I (9934) pd usbh: [init] clientHandle 0x3deb84a0 I (9934) pd usbh: [init] xTaskCreate clientEventsLoop I (9944) pd usbh: [init] success I (9944) pd log: allocated TLS for thread: usbhClientEvnts. 0x3fcd80c0. I (9944) pd usbh: [client task] started... I (9944) pd usbh: [openSingleDevice] waiting usb connection.... hal:4 port:0 hal:1 hal:1 hal:1 I (10214) pd usbh: [host task] usb_host_lib_handle_events() hal:5 port:0 hal:4 port:0 hal:1 hal:1 I (10274) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (10274) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (10284) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (10284) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 I (10294) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (10304) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (10314) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (10314) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (10324) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (10334) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (10344) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (10354) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (10354) pd usbh: [host task] usb_host_lib_handle_events() I (10374) pd usbh: [client task] NEW_DEV! addr: 1 I (10374) pd usbh: [openSingleDevice] usb_host_device_open(0x3deb84a0, usbAddress: 1, ..) I (10374) pd usbh: [host task] usb_host_lib_handle_events() I (10384) pd usbh: [openSingleDevice] deviceHandle 0x3deb85b0 I (10384) pd usbh: [host task] usb_host_lib_handle_events() I (10394) pd midi usb: open_usb_midi_device() I (10274) pd led ux: boot complete I (10404) pd usbh [device]: usb_host_device_info(dev: 0x3deb85b0) LED: solid r:0 g:255 b:0 I (10414) pd usbh [device]: usb_host_get_device_descriptor(dev:0x3deb85b0) Device descriptor: Length: 18 I (10414) pd main: BOOT COMPLETE! Descriptor type: 0x01 (Device) === Console Started === Type 'help' - get the list of commands. UP/DOWN - navigate command history. TAB - auto-complete. USB version: 0x0110 (1.1.0) Device class: 0x00 (Generic Device) Device subclass: 0x00 () Device protocol: 0x00 EP0 max packet size: 16 VID: 0x09e8 PID: 0x0076 Revision number: 1.0.0 Manufacturer id: 1 Product id: 2 Serial id: 0 Num Configurations: 1 I (10474) pd usbh [device]: getStringDescriptor(idx: 1) hal:1 hal:1 hal:1 I (10474) pd usbh: [host task] usb_host_lib_handle_events() manufacturer: 'AKAI professional LLC�' I (10484) pd usbh [device]: getStringDescriptor(idx: 2) hal:1 hal:1 hal:1 product: 'LPK25p' I (10494) pd usbh: [host task] usb_host_lib_handle_events() I (10494) pd usbh [device]: getConfigDescriptor(idx: 0) hal:1 hal:1 hal:1 I (10514) pd usbh: [host task] usb_host_lib_handle_events() Configuration: Length: 9 Descriptor type: 0x02 (Config) Total Length: 101 bNumInterfaces: 2 bConfigurationValue: 1 iConfiguration (string): 0 bmAttributes: 0xa0 bMaxPower: 100 mA Interface: Length: 9 Descriptor type: 4 (Interface) bInterfaceNumber: 0 bAlternateSetting: 0 bNumEndpoints: 0 bInterfaceClass: 0x01 (Audio) bInterfaceSubclass: 0x01 (Audio Control) bInterfaceProtocol: 0x00 iInterface (string): 0 Audio Control Interface: Length: 9 Descriptor type: 0x24 (CS Interface) Descriptor Subtype: 0x1 (Header) bcdADC: 0x0100 (AC Spec Rev 1.0.0) wTotalLength: 9 Streaming Interfaces: 1 AC Interface Idx: 1 Interface: Length: 9 Descriptor type: 4 (Interface) bInterfaceNumber: 1 bAlternateSetting: 0 bNumEndpoints: 2 bInterfaceClass: 0x01 (Audio) jmx-console> bInterfaceSubclass: 0x03 (Midi Streaming) bInterfaceProtocol: 0x00 iInterface (string): 0 Midi MS Interface: Length: 7 Descriptor type: 0x24 (CS Interface) Descriptor Subtype: 0x1 (MS Header) bcdMSC: 0x0100 (Midi Revision 1.0.0) wTotalLength: 65 Midi Jack IN Interface: Length: 6 Descriptor type: 0x24 (CS Interface) Descriptor Subtype: 0x2 (Midi IN Jack) Jack Type: 0x1 (Embedded) JackID: 1 iJack (string): 0 Midi Jack IN Interface: Length: 6 Descriptor type: 0x24 (CS Interface) Descriptor Subtype: 0x2 (Midi IN Jack) Jack Type: 0x2 (External) JackID: 2 iJack (string): 0 Midi Jack OUT Interface: Length: 9 Descriptor type: 0x24 (CS Interface) Descriptor Subtype: 0x3 (Midi OUT Jack) Jack Type: 0x1 (Embedded) JackID: 3 Input Pins: 1 [0] BaSourceID: 2 [0] BaSourcePin: 1 iJack (string): 0 Midi Jack OUT Interface: Length: 9 Descriptor type: 0x24 (CS Interface) Descriptor Subtype: 0x3 (Midi OUT Jack) Jack Type: 0x2 (External) JackID: 4 Input Pins: 1 [0] BaSourceID: 1 [0] BaSourcePin: 1 iJack (string): 0 Endpoint: Length: 9 Descriptor type: 5 (Endpoint) bEndpointAddress: 0x01 (addr: 1 Dir: Out) bmAttributes: 0x02 (Bulk) wMaxPacketSize: 64 bInterval: 0 ms Midi Bulk Endpoint: Length: 5 Descriptor type: 0x25 (CS Endpoint) Descriptor Subtype: 0x1 (MS General) Embedded Midi Jacks: 1 [0] Assoc Midi JackID: 1 Endpoint: Length: 9 Descriptor type: 5 (Endpoint) bEndpointAddress: 0x81 (addr: 1 Dir: In) bmAttributes: 0x02 (Bulk) wMaxPacketSize: 64 bInterval: 0 ms Midi Bulk Endpoint: Length: 5 Descriptor type: 0x25 (CS Endpoint) Descriptor Subtype: 0x1 (MS General) Embedded Midi Jacks: 1 [0] Assoc Midi JackID: 3 I (10824) pd midi usb: midi interfaces found: 1 I (10824) pd midi usb: Found midi 1.0 endpoint. I (10834) pd usbh [device]: setActiveConfigValue(idx: 1) hal:1 hal:1 I (10834) pd usbh: usb_host_interface_claim(0x3deb84a0, deviceHandle:0x3deb85b0 bInterfaceNumber: 1 bAlternateSetting: 0) I (10834) pd usbh: [host task] usb_host_lib_handle_events() I (10854) pd midi usb: epAddrIn: 129 I (10864) pd midi usb IN: xTaskCreate xferInTask_loop I (10864) pd midi usb: epAddrOut: 1 I (10864) pd log: allocated TLS for thread: xferInTask_loop. 0x3fcd8dcc. I (10864) pd midi usb OUT: xTaskCreate midi_usb_tx_task I (10864) pd midi usb IN: xferInTask_loop started hal:1 I (10884) pd midi usb OUT: allocate msg queue: 44000 bytes I (10894) pd midi usb IN: first Midi In. length: 64, 0x4a W (10904) pd issues: RAISE - [Atypical] | usbMidiJunk I (10904) pd_buzz: USB Device Inserted Sound W (10914) pd midi usb IN: ignore junk. superhuman? no (15ms) junk? yesbuzz C 4 523Hz 100ms W (10924) pd midi usb IN: 10.887 (usb open time) junk: 10.902 | Cb:10 Ch:4 | Note Off G#14 vel:74 junk: 10.902 | Cb:1 Misc | M? 0x61 0xbd junk: 10.902 | Cb:7 Misc | M? 0x50 0x15 junk: 10.902 | Cb:11 Misc | M? 0x69 0xae junk: 10.902 | Cb:8 Sysex Start [3B] | 0x84 0xd4 0x54 junk: 10.902 | Cb:3 Ch:8 PolyKey Press | After Touch Poly E19 pressure:191 junk: 10.902 | Cb:2 Ch:2 PolyKey Press | After Touch Poly F#14 pressure:250 junk: 10.902 | Cb:7 Ch:13 Channel Pressure | After Touch Channel 212 junk: 10.902 | Cb:10 Ch:9 PolyKey Press | After Touch Poly F#15 pressure:254 junk: 10.902 | Cb:13 Sysex Start [3B] | 0x54 0x18 0x97 junk: 10.902 | Cb:3 Sysex End [1B] | Sysex Cin Packet 0xcd junk: 10.902 | Cb:11 Ch:11 | Note Off G#4 vel:182 junk: 10.902 | Cb:15 Ch:4 Channel Pressure | After Touch Channel 241 junk: 10.902 | Cb:15 Ch:8 | Note On E4 vel:228 junk: 10.902 | Cb:2 Misc | M? 0x3a 0x2b junk: 10.902 | Cb:5 Misc | M? 0x09 0x15 I (10904) pd log: allocated TLS for thread: midi_usb_tx. 0x3fcd8bb4. I (10904) pd midi usb OUT: USB OUT task started buzz F 4 698Hz 100ms hal:3 port:2 I (11364) : e1 : [pd usbh] USB TRANSFER FAILED - no device e2 : [pd usbh [device]] submitTransferAndWait() failed e3 : [pd midi usb IN] xfer IN task: DEV GONE I (11374) pd midi usb IN: xferInTask_loop ended. wait for usb replug. I (11374) pd_buzz: USB Device Removed Sound buzz F 4 698Hz 100ms E (11364) USBH: Device 1 gone W (11394) pd usbh: [client task] DEV_GONE dev_hdl: 0x3deb85b0 W (11404) pd usbh: [close device] closing, dev_hdl: 0x3deb85b0 I (11404) pd usbh: [close device] unblocking usb transfer 3 I (11414) pd usbh: usb_host_interface_release(0x3deb84a0, device: 0x3deb85b0, bInterfaceNumber: 1 I (11424) pd usbh: interface fully released I (11424) pd usbh: [close device] usb_host_device_close(client:0x3deb84a0,dev:0x3deb85b0) I (11444) pd usbh: [close device] 0 devices still open I (11404) pd usbh: [host task] usb_host_lib_handle_events() I (11444) pd usbh: [host task] event: USB_HOST_LIB_EVENT_FLAGS - ALL_FREE I (11454) pd usbh: [host task] usb_host_lib_handle_events() I (11454) pd usbh: [host task] usb_host_lib_handle_events() buzz C 4 523Hz 100ms I (11594) pd usbh: [uninitialize] called I (11594) pd usbh: [uninitialize] got mutex I (11594) pd usbh: cancelAllTransfers() I (11594) pd usbh: [uninitialize] Stopping xUsbClientTask... I (11604) pd usbh: [uninitialize] usb_host_client_unblock(client:0x3deb84a0) I (11734) pd usbh: [client task] vTaskDelete() I (12134) xesp usb parse: Free config pool I (12134) pd usbh: [openSingleDevice] called I (12134) pd usbh: [openSingleDevice] all devices closed. continuing... I (12154) pd usbh: [openSingleDevice] initializing usbh I (12154) pd usbh: [init] initialize hal:2 port:1 I (12614) pd usbh: [uninitialize] xUsbClientTask completed I (12614) pd usbh: [uninitialize] 0 devices need closing I (12614) pd usbh: closeAllDevices() I (12624) pd usbh: closeAllDevices() complete I (12624) pd usbh: [uninitialize] usb_host_client_deregister(client:0x3deb84a0) I (12634) pd usbh: [uninitialize] Stopping xUsbHostTask... I (12634) pd usbh: [uninitialize] usb_host_lib_unblock() hal:4 port:0 hal:1 hal:1 hal:1 I (12774) pd usbh: [host task] event: USB_HOST_LIB_EVENT_FLAGS - NO_CLIENTS I (12774) pd usbh: [host task] usb_host_device_free_all() I (12784) pd usbh: [host task] usb_host_lib_handle_events() hal:5 port:0 hal:4 port:0 hal:1 hal:1 I (12844) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (12844) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (12854) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (12854) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 I (12874) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (12874) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (12884) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (12884) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (12894) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (12904) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (12914) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (12924) pd usbh: [host task] usb_host_lib_handle_events() hal:1 hal:1 hal:1 I (12934) pd usbh: [host task] usb_host_lib_handle_events() I (12944) pd usbh: [host task] usb_host_lib_handle_events() I (12944) pd usbh: [host task] usb_host_lib_handle_events() I (13064) pd usbh: [host task] vTaskDelete() I (13654) pd usbh: [uninitialize] uxUsbHostTask completed I (13654) pd usbh: [uninitialize] usb_host_uninstall() process_pending_flags 0 lib_event_flags 0 flags.val 0 hal:3 port:2 ESP_ERROR_CHECK failed: esp_err_t 0x103Guru Meditation Error: Core 1 panic'ed (LoadProhibited). Exception was unhandled. Core 1 register dump: PC : 0x42087639 PS : 0x00060f33 A0 : 0x8208664d A1 : 0x3fca1d80 0x42087639: root_port_callback at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/usb/hub.c:703 A2 : 0x3fcd4bec A3 : 0x00000002 A4 : 0x00000000 A5 : 0x00000001 A6 : 0x00060023 A7 : 0x00060022 A8 : 0x3fcac374 A9 : 0x00000000 A10 : 0x00000001 A11 : 0xa23311f5 A12 : 0xa23311f5 A13 : 0x3fca79ac A14 : 0x00060f23 A15 : 0x00060f22 SAR : 0x00000004 EXCCAUSE: 0x0000001c EXCVADDR: 0x00000000 LBEG : 0x00000000 LEND : 0x00000000 LCOUNT : 0x00000000 Backtrace:0x42087636:0x3fca1d800x4208664a:0x3fca1db0 0x40378fc1:0x3fca1de0 0x420c50cc:0x3fcf5820 0x42006349:0x3fcf5850 0x403853eb:0x3fcf5880 0x40388252:0x3fcf58b0 0x42087636: root_port_callback at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/usb/hub.c:703 0x4208664a: intr_hdlr_main at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/usb/hcd.c:956 0x40378fc1: _xt_medint2 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1200 0x420c50cc: cpu_ll_waiti at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/hal/esp32s3/include/hal/cpu_ll.h:182 (inlined by) esp_pm_impl_waiti at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/esp_pm/pm_impl.c:837 0x42006349: esp_vApplicationIdleHook at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/esp_system/freertos_hooks.c:63 0x403853eb: prvIdleTask at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/tasks.c:3973 (discriminator 1) 0x40388252: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/port/xtensa/port.c:131 ELF file SHA256: 6ba9c090eb1d360d I (10963) esp_core_dump_flash: Save core dump to flash... I (10969) esp_core_dump_flash: Erase flash 53248 bytes @ 0x10000 I (11705) esp_core_dump_flash: Write end offset 0xc4a4, check sum length 4 I (11705) esp_core_dump_flash: Core dump has been saved to flash. CPU halted. ```

[chipweinberger]

bump =)

[chipweinberger]

@Dazza0 , did you ever get a chance to reason about this?

Does root_port_handle_events() need to handle HUB_DRIVER_STATE_ROOT_RECOVERY?

[chipweinberger]

Another bump!

[chipweinberger]

bump! Have there been any changes around this?

[chipweinberger]

bump again

[chipweinberger]

did we ever get to the bottom of this?

[chipweinberger]

I'm still hitting this on v5.1.2!

Crash when unplugging usb device

 (10768) pd midi usb IN: 10.326 (usb open time)
junk: 10.328 | Cb:0 Ch:0  | Note Off A#4 vel:127
jmx-console> I (11568) pd usbh: wait for all devices to close...
E (11968) USBH: Device 1 gone
semaphore: 14
I (11968) : e1 : [pd usbh] USB TRANSFER FAILED - no device
e2 : [pd usbh [device]] pd_usbh_service_submitTransferAndWait() failed.
e3 : [pd midi usb IN] xfer IN task: DEV GONE

W (11968) pd usbh: [client task] DEV_GONE dev_hdl: 0x3c3b7100
I (11968) pd midi usb IN: xferInTask_loop ended. wait for usb replug.
I (11978) pd alerts: notify usb
I (11978) pd buzz: USB Device Removed Sound
W (11978) pd usbh: [close device] closing, dev_hdl: 0x3c3b7100
buzz F 4 698Hz 100ms
I (11978) pd usbh: [close device] unblocking usb transfer 3
I (11978) pd usbh: usb_host_interface_release(0x3c3b609c, device: 0x3c3b7100, bInterfaceNumber: 1
I (11988) pd usbh: interface fully released
I (11988) pd usbh: [close device] usb_host_device_close(client:0x3c3b609c,dev:0x3c3b7100)
I (11988) pd usbh: [close device] 0 devices still open
I (11968) pd usbh: [host task] usb_host_lib_handle_events()

abort() was called at PC 0x42090a07 on core 0
0x42090a07: root_port_handle_events at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/usb/hub.c:838
 (inlined by) hub_process at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/usb/hub.c:1043

Backtrace: 0x40376037:0x3c3b5c00 0x40384b3d:0x3c3b5c30 0x4038d837:0x3c3b5c60 0x42090a07:0x3c3b5ce0 0x4208b49b:0x3c3b5d30 0x4204777f:0x3c3b5d70 0x40385aae:0x3c3b5da0
0x40376037: panic_abort at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/esp_system/panic.c:452

0x40384b3d: esp_system_abort at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/esp_system/port/esp_system_chip.c:84

0x4038d837: abort at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/newlib/abort.c:38

0x42090a07: root_port_handle_events at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/usb/hub.c:838
 (inlined by) hub_process at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/usb/hub.c:1043

0x4208b49b: usb_host_lib_handle_events at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/usb/usb_host.c:515

0x4204777f: usbHostTaskLoop(void*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jcommon/usb/pd_usbh_service.cpp:70

0x40385aae: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162