Skip to content
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

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

Open
chipweinberger opened this issue Sep 2, 2022 · 10 comments
Open

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

chipweinberger opened this issue Sep 2, 2022 · 10 comments
Assignees
@Dazza0
Labels
Status: Selected for Development Issue is selected for development

Comments

@chipweinberger
Copy link
Contributor

chipweinberger commented Sep 2, 2022 •
edited
Loading

General issue report

ESP-IDF v4.4.2
ESP32-S3

See original issue: #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 chipweinberger mentioned this issue Sep 2, 2022
Closed
@espressif-bot espressif-bot added the Status: Opened Issue is new label Sep 2, 2022
@github-actions github-actions bot changed the title [USB][ABORT][v4.4.2] root_port_handle_events() hits HUB_DRIVER_STATE_ROOT_RECOVERY [USB][ABORT][v4.4.2] root_port_handle_events() hits HUB_DRIVER_STATE_ROOT_RECOVERY (IDFGH-8214) Sep 2, 2022
@chipweinberger
Copy link
Contributor Author

chipweinberger commented Sep 2, 2022 •
edited
Loading

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_PORT_EVENT_... 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
Copy link
Contributor Author

chipweinberger commented Sep 3, 2022 •
edited
Loading

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
Copy link
Contributor Author

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
Copy link
Contributor Author

bump =)

@chipweinberger
Copy link
Contributor Author

chipweinberger commented Nov 9, 2022 •
edited
Loading

@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
Copy link
Contributor Author

Another bump!

@chipweinberger
Copy link
Contributor Author

chipweinberger commented Jan 5, 2023 •
edited
Loading

bump! Have there been any changes around this?

@espressif-bot espressif-bot added Status: Selected for Development Issue is selected for development and removed Status: Opened Issue is new labels Apr 13, 2023
@chipweinberger
Copy link
Contributor Author

bump again

@chipweinberger
Copy link
Contributor Author

did we ever get to the bottom of this?

@chipweinberger
Copy link
Contributor Author

chipweinberger commented Mar 12, 2024 •
edited
Loading

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

@chipweinberger chipweinberger mentioned this issue Mar 12, 2024
Open
3 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Dazza0 Dazza0

Labels
Status: Selected for Development Issue is selected for development
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@chipweinberger @Dazza0 @espressif-bot