esp-idf icon indicating copy to clipboard operation
esp-idf copied to clipboard
verified publisher icon espressif

[v5.1.4][s3] `usb_serial_jtag_is_connected` doesn't detect my computer ~10% of the time (IDFGH-12984)

Open chipweinberger opened this issue 1 year ago • 10 comments

Answers checklist.

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

IDF version.

v5.1.4

Espressif SoC revision.

ESP32-s3

Operating System used.

macOS

How did you build your project?

Command line with idf.py

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

None

Development Kit.

custom pcb

Power Supply used.

USB

What is the expected behavior?

I expect usb_serial_jtag_is_connected to always work

What is the actual behavior?

~10% of the time, USJ is connected, but usb_serial_jtag_is_connected returns false

Steps to reproduce.

With idf.py monitor:

  1. plug in USJ to PC
  2. device boots up
  3. run idf.py monitor
  4. device reboots
  5. ~16 seconds after boot, I check usb_serial_jtag_is_connected and it returns false

More Information.

No response

chipweinberger avatar Jun 08 '24 22:06 chipweinberger

Using Visual Studio Code I can also repro by doing this:

  1. plug in USJ to PC
  2. device boots up
  3. click 'Terminal' button in VSC
  4. device reboots
  5. USJ is detected, serial console works (90% of the time!) .... repeat steps 3,4,5 again and again, until eventually....
  6. USJ is not detected, serial console disabled by my firmware

chipweinberger avatar Jun 08 '24 22:06 chipweinberger

@mythbuster5

@songruo

@igrr

Anything I can look into?

chipweinberger avatar Jun 21 '24 11:06 chipweinberger

this problem is very annoying

chipweinberger avatar Aug 12 '24 22:08 chipweinberger

@chipweinberger If you increase the value here, does it help you?

songruo avatar Aug 16 '24 07:08 songruo

I'll do some testing soon.

Here is my CMakeLists.txt

CMakeLists 
CONFIG_IDF_TARGET="esp32s3"
CONFIG_BOOTLOADER_WDT_ENABLE=y
CONFIG_BOOTLOADER_WDT_TIME_MS=120000
CONFIG_ESPTOOLPY_FLASHSIZE_8MB=y
CONFIG_ESPTOOLPY_MONITOR_BAUD=921600
CONFIG_PARTITION_TABLE_CUSTOM=y
CONFIG_PARTITION_TABLE_CUSTOM_FILENAME="partitions.csv"
CONFIG_PARTITION_TABLE_OFFSET=0xf000
CONFIG_COMPILER_OPTIMIZATION_PERF=y
CONFIG_COMPILER_CXX_EXCEPTIONS=y
CONFIG_COMPILER_CXX_EXCEPTIONS_EMG_POOL_SIZE=2048
CONFIG_COMPILER_STACK_CHECK_MODE_ALL=y
CONFIG_COMPILER_STACK_CHECK=y
CONFIG_COMPILER_WARN_WRITE_STRINGS=y

CONFIG_BT_ENABLED=y
CONFIG_BT_NIMBLE_ENABLED=y
CONFIG_BT_NIMBLE_MEM_ALLOC_MODE_EXTERNAL=y
CONFIG_BT_NIMBLE_MAX_CONNECTIONS=8
CONFIG_BT_NIMBLE_PINNED_TO_CORE_0=y
CONFIG_BT_NIMBLE_HOST_TASK_STACK_SIZE=5120
CONFIG_BT_NIMBLE_NVS_PERSIST=y
CONFIG_BT_NIMBLE_USE_ESP_TIMER=y
CONFIG_BT_NIMBLE_MSYS_1_BLOCK_COUNT=18
CONFIG_BT_NIMBLE_MSYS_2_BLOCK_COUNT=36

CONFIG_HTTPD_MAX_REQ_HDR_LEN=2048
CONFIG_HTTPD_MAX_URI_LEN=2048
CONFIG_HTTPD_WS_SUPPORT=y

CONFIG_SPIRAM=y
CONFIG_SPIRAM_ALLOW_STACK_EXTERNAL_MEMORY=y
CONFIG_SPIRAM_CLK_IO=30
CONFIG_SPIRAM_CS_IO=26
CONFIG_SPIRAM_USE_MALLOC=y
CONFIG_SPIRAM_MALLOC_ALWAYSINTERNAL=94
CONFIG_SPIRAM_TRY_ALLOCATE_WIFI_LWIP=y
CONFIG_SPIRAM_MALLOC_RESERVE_INTERNAL=40960
CONFIG_ESP_CONSOLE_USE_PSRAM=y

CONFIG_ESP_DEFAULT_CPU_FREQ_MHZ_240=y
CONFIG_ESP32S3_DATA_CACHE_16KB=y
CONFIG_ESP_SYSTEM_PANIC_PRINT_REBOOT=y
CONFIG_ESP_SYSTEM_PANIC_REBOOT_DELAY_SECONDS=4
CONFIG_ESP_SYSTEM_EVENT_TASK_STACK_SIZE=4096
CONFIG_ESP_MAIN_TASK_STACK_SIZE=8192

CONFIG_ESP_CONSOLE_UART_CUSTOM=y
CONFIG_ESP_CONSOLE_UART_CUSTOM_NUM_0=y
CONFIG_ESP_CONSOLE_UART_TX_GPIO=43
CONFIG_ESP_CONSOLE_UART_RX_GPIO=44
CONFIG_ESP_CONSOLE_UART_BAUDRATE=921600

CONFIG_ESP_INT_WDT_TIMEOUT_MS=10000
CONFIG_ESP_TASK_WDT_PANIC=y
CONFIG_ESP_TASK_WDT_TIMEOUT_S=60
CONFIG_ESP_IPC_TASK_STACK_SIZE=2048
CONFIG_ESP_TIMER_TASK_STACK_SIZE=4096

CONFIG_ESP_WIFI_STATIC_RX_BUFFER_NUM=6
CONFIG_ESP_WIFI_STATIC_TX_BUFFER=y
CONFIG_ESP_WIFI_TX_BUFFER_TYPE=0
CONFIG_ESP_WIFI_STATIC_TX_BUFFER_NUM=8
CONFIG_ESP_WIFI_CACHE_TX_BUFFER_NUM=32
CONFIG_ESP_WIFI_TX_BA_WIN=8
CONFIG_ESP_WIFI_RX_BA_WIN=12

CONFIG_ESP_COREDUMP_ENABLE_TO_FLASH=y
CONFIG_ESP_COREDUMP_DATA_FORMAT_ELF=y
CONFIG_ESP_COREDUMP_CHECKSUM_CRC32=y
CONFIG_ESP_COREDUMP_ENABLE=y
CONFIG_ESP_COREDUMP_MAX_TASKS_NUM=64
CONFIG_ESP_COREDUMP_USE_STACK_SIZE=y
CONFIG_ESP_COREDUMP_STACK_SIZE=1280

CONFIG_FATFS_LFN_HEAP=y
CONFIG_FATFS_MAX_LFN=255
CONFIG_FATFS_API_ENCODING_ANSI_OEM=y
CONFIG_FATFS_FS_LOCK=16
CONFIG_FATFS_ALLOC_PREFER_EXTRAM=y

CONFIG_FREERTOS_THREAD_LOCAL_STORAGE_POINTERS=3
CONFIG_FREERTOS_IDLE_TASK_STACKSIZE=1880
CONFIG_FREERTOS_TIMER_TASK_STACK_DEPTH=4096
CONFIG_FREERTOS_USE_TRACE_FACILITY=y
CONFIG_FREERTOS_USE_STATS_FORMATTING_FUNCTIONS=y
CONFIG_FREERTOS_VTASKLIST_INCLUDE_COREID=y
CONFIG_FREERTOS_GENERATE_RUN_TIME_STATS=y

CONFIG_FREERTOS_WATCHPOINT_END_OF_STACK=y
CONFIG_FREERTOS_ISR_STACKSIZE=2096
CONFIG_FREERTOS_RUN_TIME_STATS_USING_ESP_TIMER=y
CONFIG_FREERTOS_PLACE_SNAPSHOT_FUNS_INTO_FLASH=y

CONFIG_HEAP_POISONING_COMPREHENSIVE=y
CONFIG_HEAP_ABORT_WHEN_ALLOCATION_FAILS=y

CONFIG_LWIP_MAX_SOCKETS=16
CONFIG_LWIP_MAX_ACTIVE_TCP=32
CONFIG_LWIP_MAX_LISTENING_TCP=32
CONFIG_LWIP_TCP_SND_BUF_DEFAULT=6500
CONFIG_LWIP_TCP_WND_DEFAULT=6500
CONFIG_LWIP_TCPIP_TASK_STACK_SIZE=4096

CONFIG_MBEDTLS_HARDWARE_AES=n
CONFIG_MBEDTLS_MPI_USE_INTERRUPT=n

CONFIG_PTHREAD_TASK_STACK_SIZE_DEFAULT=4096

CONFIG_MDNS_TASK_STACK_SIZE=3072
CONFIG_MONITOR_BAUD=921600

chipweinberger avatar Aug 21 '24 22:08 chipweinberger

I've added print statements to periodically print the value of usb_serial_jtag_is_connected() during boot.

You can see it is "1" (true) for nearly the entire boot, but then switches to "0"

Coincidentally, it switches to 0 right before I actually use it in my code, so that probably causes the "~10%" problem. Unlucky timing.

Logs 
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x15 (USB_UART_CHIP_RESET),boot:0x2b (SPI_FAST_FLASH_BOOT)
Saved PC:0x400490d5
0x400490d5: usb_uart_device_rx_one_char in ROM

SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3af0,len:0x23e4
load:0x403c9700,len:0x4
load:0x403c9704,len:0x1c94
load:0x403cc700,len:0x2e68
entry 0x403c9a8c
I (32) boot: ESP-IDF v5.1.4 2nd stage bootloader
I (32) boot: compile time Jun  2 2024 22:27:20
I (32) boot: Multicore bootloader
I (33) boot: chip revision: v0.2
I (33) boot.esp32s3: Boot SPI Speed : 80MHz
I (35) boot.esp32s3: SPI Mode       : DIO
I (36) boot.esp32s3: SPI Flash Size : 8MB
I (37) boot: Enabling RNG early entropy source...
I (39) boot: Partition Table:
I (39) boot: ## Label            Usage          Type ST Offset   Length
I (41) boot:  0 jOtaData         OTA data         01 00 00010000 00002000
I (43) boot:  1 jCoredump        Unknown data     01 03 00012000 00010000
I (45) boot:  2 nvsKeys          NVS keys         01 04 00022000 00001000
I (47) boot:  3 jPhyInit         RF data          01 01 00023000 00001000
I (49) boot:  4 efuse_em         efuse            01 05 00024000 00001000
I (50) boot:  5 jOtaAesKey       Unknown data     01 06 00025000 00001000
I (52) boot:  6 jFabInfo         Unknown data     01 06 00026000 00013000
I (54) boot:  7 jStSafe          Unknown data     01 06 00039000 00004000
I (56) boot:  8 jJamcorderUuid   Unknown data     01 06 0003d000 00001000
I (58) boot:  9 nvs              WiFi data        01 02 0003e000 00033000
I (60) boot: 10 jSafeBoot        Unknown data     01 06 00071000 00006000
I (62) boot: 11 jDevCmds         Unknown data     01 06 00077000 00004000
I (63) boot: 12 jLifeStats       Unknown data     01 06 0007b000 00042000
I (65) boot: 13 jImmortal        Unknown data     01 06 000bd000 00008000
I (67) boot: 14 jJfuArgs         Unknown data     01 06 000c5000 00008000
I (69) boot: 15 jJfwmArgs        Unknown data     01 06 000cd000 00008000
I (71) boot: 16 jExtra1          Unknown data     01 06 000d5000 00004000
I (73) boot: 17 jExtra2          Unknown data     01 06 000d9000 00004000
I (75) boot: 18 jExtra3          Unknown data     01 06 000dd000 00002000
I (77) boot: 19 jExtra4          Unknown data     01 06 000df000 00001000
I (78) boot: 20 jJfuApp          OTA app          00 11 000e0000 00220000
I (80) boot: 21 jJfwmApp         OTA app          00 10 00300000 00500000
I (82) boot: End of partition table
E (83) boot: ota data partition invalid and no factory, will try all partitions
I (85) jboot: bootloader_utility_get_selected_boot_partition: -1
I (87) jboot: Clearing ota_data Partition...
I (88) boot_comm: ## Label            Usage Offset   Length   Cleaned
I (121) boot_comm:  0 jOtaData         data  00010000 00002000 [yes]
I (122) boot_comm:  1 jCoredump        data  00012000 00010000 [no]
I (122) boot_comm:  2 nvsKeys          data  00022000 00001000 [no]
I (124) boot_comm:  3 jPhyInit         data  00023000 00001000 [no]
I (125) boot_comm:  4 efuse_em         data  00024000 00001000 [no]
I (127) boot_comm:  5 jOtaAesKey       data  00025000 00001000 [no]
I (129) boot_comm:  6 jFabInfo         data  00026000 00013000 [no]
I (131) boot_comm:  7 jStSafe          data  00039000 00004000 [no]
I (132) boot_comm:  8 jJamcorderUuid   data  0003d000 00001000 [no]
I (134) boot_comm:  9 nvs              data  0003e000 00033000 [no]
I (136) boot_comm: 10 jSafeBoot        data  00071000 00006000 [no]
I (138) boot_comm: 11 jDevCmds         data  00077000 00004000 [no]
I (139) boot_comm: 12 jLifeStats       data  0007b000 00042000 [no]
I (141) boot_comm: 13 jImmortal        data  000bd000 00008000 [no]
I (143) boot_comm: 14 jJfuArgs         data  000c5000 00008000 [no]
I (145) boot_comm: 15 jJfwmArgs        data  000cd000 00008000 [no]
I (146) boot_comm: 16 jExtra1          data  000d5000 00004000 [no]
I (148) boot_comm: 17 jExtra2          data  000d9000 00004000 [no]
I (150) boot_comm: 18 jExtra3          data  000dd000 00002000 [no]
I (151) boot_comm: 19 jExtra4          data  000df000 00001000 [no]
I (153) jboot: Note: Hold User Button down during boot to see boot menu!
I (155) jboot: Waiting 1.5 seconds for user to press button...
I (1655) jboot: GPIO not held
I (1655) jboot: GPIO hold time: 0
I (1655) jboot: No command chosen. Entering Default App Mode
I (1655) esp_image: segment 0: paddr=00300020 vaddr=3c190020 size=f87bch (1017788) map
I (1864) esp_image: segment 1: paddr=003f87e4 vaddr=3fca2400 size=06494h ( 25748) load
I (1870) esp_image: segment 2: paddr=003fec80 vaddr=40374000 size=01398h (  5016) load
I (1872) esp_image: segment 3: paddr=00400020 vaddr=42000020 size=189b40h (1612608) map
I (2199) esp_image: segment 4: paddr=00589b68 vaddr=40375398 size=1cf70h (118640) load
I (2241) boot: Loaded app from partition at offset 0x300000
I (2241) boot: Disabling RNG early entropy source...
I (2244) cpu_start: Multicore app
I (2245) esp_psram: Found 2MB PSRAM device
I (2245) esp_psram: Speed: 40MHz
I (2245) cpu_start: Pro cpu up.
I (2245) cpu_start: Starting app cpu, entry point is 0x4037590c
0x4037590c: call_start_cpu1 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/esp_system/port/cpu_start.c:159

I (0) cpu_start: App cpu up.
I (2733) esp_psram: SPI SRAM memory test OK
I (2742) cpu_start: Pro cpu start user code
I (2743) cpu_start: cpu freq: 240000000 Hz
I (2743) cpu_start: Application information:
I (2743) cpu_start: Project name:     jJfwmApp
I (2745) cpu_start: App version:      v1.1.3-1724277762
I (2746) cpu_start: Compile time:     Aug 21 2024 17:03:08
I (2748) cpu_start: ELF file SHA256:  a27f03f884c207aa...
I (2749) cpu_start: ESP-IDF:          v5.1.4
I (2750) cpu_start: Min chip rev:     v0.0
I (2752) cpu_start: Max chip rev:     v0.99 
I (2753) cpu_start: Chip rev:         v0.2
I (2754) heap_init: Initializing. RAM available for dynamic allocation:
I (2756) heap_init: At 3FCB4620 len 000350F0 (212 KiB): DRAM
I (2757) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (2759) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (2761) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
I (3044) esp_psram: Adding pool of 2048K of PSRAM memory to heap allocator
I (3046) spi_flash: detected chip: gd
I (3046) spi_flash: flash io: dio
I (3048) sleep: Configure to isolate all GPIO pins in sleep state
I (3049) sleep: Enable automatic switching of GPIO sleep configuration
I (3049) esp_core_dump_flash: Init core dump to flash
I (3051) esp_core_dump_flash: Found partition 'jCoredump' @ 12000 65536 bytes
E (3053) esp_core_dump_flash: Incorrect size of core dump image: 248652817
I (3055) coexist: coex firmware version: d96c1e51f
I (3056) coexist: coexist rom version e7ae62f
I (3058) app_start: Starting scheduler on CPU0
I (0) app_start: Starting scheduler on CPU1
I (3059) main_task: Started on CPU0
I (3069) esp_psram: Reserving pool of 40K of internal memory for DMA/internal allocations
I (3069) main_task: Calling app_main()
I (3069) pd main: app_main() called
E (3069) pd main: usb_serial_jtag_is_connected() 1
I (3069) pd main: LED - set solid green
I (3069) gpio: GPIO[2]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
E (3079) pd main: usb_serial_jtag_is_connected() 1
I (3079) pd safe boot: get
I (3079) pd safe boot: jJamBootCount 0
I (3079) pd safe boot: clear
I (3079) pd safe boot: erased 0 sectors
I (3089) pd safe boot: incremented to 1
E (3089) pd main: usb_serial_jtag_is_connected() 1
I (3089) pd main: Internal RAM: 243999 bytes free
I (3089) pd main: SPI RAM: 2091684 bytes free
I (3089) pd main: Bluetooth RAM: 196096
I (3089) pd main: turn off SD card
I (3089) gpio: GPIO[18]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (3189) pd main: turn on SD card
E (3439) pd main: usb_serial_jtag_is_connected() 1
I (3439) pd global mutex: init
E (3439) pd main: usb_serial_jtag_is_connected() 1
E (3439) pd main: usb_serial_jtag_is_connected() 1
I (3439) pd file: init
I (3439) pd sfile: init
E (3439) pd main: usb_serial_jtag_is_connected() 1
E (3439) pd main: usb_serial_jtag_is_connected() 1
I (3439) pd http ws clients: init
I (3479) pd log: replace logging function with 0x420255b8
0x420255b8: pd_log_vprintf(char const*, __va_list_tag) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jcommon/logs/pd_log.cpp:226

E (3479) pd main: usb_serial_jtag_is_connected() 1
E (3479) pd main: usb_serial_jtag_is_connected() 1
I (3479) pd main: ====== RESET REASON ======
I (3479) pd main:   unknown
I (3479) pd main: ==========================
E (3489) pd main: usb_serial_jtag_is_connected() 1
I (3489) pd developer: init
I (3489) pd developer: no developer settings found
E (3489) pd main: usb_serial_jtag_is_connected() 1
I (3489) pd flash enc: checking flash encryption fuses
I (3489) pd flash enc: encryption IS enabled
I (3489) pd flash enc: Checking: DIS_DOWNLOAD_MANUAL_ENCRYPT
I (3499) pd flash enc: Checking: DIS_DIRECT_BOOT
I (3499) pd flash enc: Checking: DIS_DOWNLOAD_ICACHE
I (3499) pd flash enc: Checking: DIS_DOWNLOAD_DCACHE
I (3499) pd flash enc: Checking: HARD_DIS_JTAG
I (3499) pd flash enc: Checking: DIS_USB_JTAG
   __                                    _            
   \ \  __ _ _ __ ___   ___ ___  _ __ __| | ___ _ __  
    \ \/ _` | '_ ` _ \ / __/ _ \| '__/ _` |/ _ \ '__| 
 /\_/ / (_| | | | | | | (_| (_) | | | (_| |  __/ |    
 \___/ \__,_|_| |_| |_|\___\___/|_|  \__,_|\___|_|    

---------------------------------------------
  ___ ___  _ __  ___ _   _ _ __ ___   ___ _ __ 
 / __/ _ \| '_ \/ __| | | | '_ ` _ \ / _ \ '__|
| (_| (_) | | | \__ \ |_| | | | | | |  __/ |   
 \___\___/|_| |_|___/\__,_|_| |_| |_|\___|_|   
-----------------------------------------------
I (3509) pd main: Running Partition: jJfwmApp size: 5120KB
I (3519) pd main: Running ESP-IDF Ver: v5.1.4
E (3519) pd main: usb_serial_jtag_is_connected() 1
json read: (length 531) {
	"fabUnixtime":	1718971020,
	"fabProductKey":	"ac777ff82d801401e38257bdb4fae7d926be28e32c54b9dc0c4265388b1f8a65",
	"fabModelNumber":	"JMX100",
	"fabPcbRev":	"J",
	"fabTrain":	"prod",
	"fabJmxGitBranchName":	"master",
	"fabJmxGitCommitHash":	"709b1feb33905a9cfd8799ab6c776ef7a6992635",
	"fabJmxGitCommitUnixtime":	1718940563,
	"fabEspIdfVersion":	"v5.1.4",
	"fabEspIdfGitBranchName":	"user/chip/v5.1.4-production",
	"fabEspIdfGitCommitHash":	"d7b0a45ddbddbac53afb4fc28168f9f9259dbb79",
	"fabEspIdfGitCommitUnixtime":	1715250918
}
I (3529) pd fab info: {
	"fabUnixtime":	1718971020,
	"fabProductKey":	"ac777ff82d801401e38257bdb4fae7d926be28e32c54b9dc0c4265388b1f8a65",
	"fabModelNumber":	"JMX100",
	"fabPcbRev":	"J",
	"fabTrain":	"prod",
	"fabJmxGitBranchName":	"master",
	"fabJmxGitCommitHash":	"709b1feb33905a9cfd8799ab6c776ef7a6992635",
	"fabJmxGitCommitUnixtime":	1718940563,
	"fabEspIdfVersion":	"v5.1.4",
	"fabEspIdfGitBranchName":	"user/chip/v5.1.4-production",
	"fabEspIdfGitCommitHash":	"d7b0a45ddbddbac53afb4fc28168f9f9259dbb79",
	"fabEspIdfGitCommitUnixtime":	1715250918,
	"fabPhysicalId":	"127c6aff632617ecec9a12bda1831350"
}
E (3539) pd main: usb_serial_jtag_is_connected() 1
E (3549) pd main: usb_serial_jtag_is_connected() 1
I (3549) pd buzz: init
E (3549) pd main: usb_serial_jtag_is_connected() 1
I (3549) pd led: init
I (3549) pd led: xTaskCreate led task
I (3549) pd led: led task started
LED: setting master brightness 0 / 1000
I (3549) pd led ux: booting
LED: blink r:0 g:255 b:0
E (3549) pd main: usb_serial_jtag_is_connected() 1
I (3559) pd main: Start Low Ram Check Timer
E (3559) pd main: usb_serial_jtag_is_connected() 1
I (3559) pd main: calling gpio_install_isr_service()
E (3559) pd main: usb_serial_jtag_is_connected() 1
I (3559) pd user button: xTaskCreate user_button_task
I (3559) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 
E (3569) pd main: usb_serial_jtag_is_connected() 1
I (3569) pd nvs: init
I (3569) pd nvs: initialize keys
I (3569) pd nvs: calling nvs_flash_init()
I (3679) pd nvs: calling nvs_open_from_partition(nvs,jmx,NVS_READWRITE,...)
I (3689) pd nvs print: logging all entries:
I (3699) pd nvs print: MidiRecordSysex : u8 : 1
I (3699) pd nvs print: MidiSilenceSkip : u8 : 1
I (3699) pd nvs print: MidiMaxSilence  : u32 : 3000
I (3699) pd nvs print: CmdOctave       : u8 : 7
I (3699) pd nvs print: PerformerUuid   : string : eed79959-3d2a-742a-67ea-a6e7ccb
I (3699) pd nvs print: ClockYearOffset : u16 : 0
I (3699) pd nvs print: TimeTzSetByUser : u8 : 1
I (3709) pd nvs print: ClockTimeSource : u8 : 4
I (3709) pd nvs print: TimeDls         : blob : 1616 bytes 0x903b2767...
I (3709) pd nvs print: JamcorderName   : string : PCBWay-RevN-1
I (3719) pd nvs print: PerformerName   : string : Chip Weinberger
I (3719) pd nvs print: TimeLocalOffset : i16 : -420
I (3719) pd nvs print: ClockStartTime  : u64 : 1720653652
I (3719) pd nvs print: BootCount       : u32 : 21
I (3719) pd nvs print: MidiAssetCount  : 
I (3719) pd nvs print: MidiBookmkCount : 
I (3719) pd nvs print: CmdDisableAll   : 
I (3729) pd nvs print: CmdDisablePlay  : 
I (3729) pd nvs print: CmdDisableBook  : 
I (3729) pd nvs print: CmdSafeNote     : 
I (3729) pd nvs print: TimeSntpDisable : 
I (3729) pd nvs print: WifiHomeSsid    : 
I (3729) pd nvs print: WifiHomePasswrd : 
I (3729) pd nvs print: BootDiscovery   : 
I (3729) pd nvs print: BootNewHomeCred : 
I (3729) pd nvs print: BootHomeWifiErr : 
I (3739) pd nvs print: VerboseTagNums  : 
I (3739) pd nvs print: CoredumpTime    : 
I (3739) pd nvs print: CoredumpSha256  : 
I (3739) pd nvs print: DisableBuzzer   : 
E (3739) pd main: usb_serial_jtag_is_connected() 1
E (3749) pd main: usb_serial_jtag_is_connected() 1
E (3749) pd main: usb_serial_jtag_is_connected() 1
I (3749) pd verbose: init
E (3749) pd main: usb_serial_jtag_is_connected() 1
E (3749) pd main: usb_serial_jtag_is_connected() 1
I (3749) 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
E (4469) pd main: usb_serial_jtag_is_connected() 1
I (4469) pd boot args jam: one time read
E (4469) pd main: usb_serial_jtag_is_connected() 1
json read: (length 61) {
	"jamcorderUuid":	"96ac38aa-b312-c090-2707-60c1a10b72ba"
}
E (4469) pd main: usb_serial_jtag_is_connected() 1
E (4469) pd main: usb_serial_jtag_is_connected() 1
I (4469) pd time: init
I (4469) pd time: turn on DS1302
I (4569) pd localtime: init
I (4569) pd localtime: settimeofday updated 1724253913
I (4569) pd time: [init] current unixtime: 2024-8-21 22:25:13 weekday: 4 year_offset: 0
I (4569) pd time: [init] timeSource: app
I (4569) pd time: [init] yearOffset: 0
I (4569) pd time: [init] clockStartTime: 1720653652
E (4569) pd main: usb_serial_jtag_is_connected() 1
I (4579) pd main: Localtime Offset: -420
E (4579) pd main: usb_serial_jtag_is_connected() 1
I (4579) pd coredump check: checking for new coredump
E (4578) esp_core_dump_flash: Incorrect size of core dump image: 248652817
I (4579) pd coredump check: esp_core_dump_image_check() - no valid coredump found. ESP_ERR_INVALID_SIZE
I (4579) pd main: no new coredump found
E (4579) pd main: usb_serial_jtag_is_connected() 1
I (4589) pd stsafe: init
I (4589) gpio: GPIO[11]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (4989) pd stsafe intf: IOInit
I (4989) pd stsafe intf: BusInit
I (4989) pd i2c: init
I (4989) pd i2c: driver installed
I (4989) pd stsafe utils: Reset
I (4989) pd stsafe intf: BusSend (3 bytes)
I (4989) pd stsafe intf: TimeDelay (30ms)
I (5019) pd stsafe intf: BusRecv (5 bytes)
I (5019) pd stsafe utils: Are Host Keys Present?
I (5019) pd stsafe intf: BusSend (4 bytes)
I (5019) pd stsafe intf: TimeDelay (5ms)
I (5029) pd stsafe intf: BusRecv (9 bytes)
I (5029) pd stsafe utils: No. Host keys are NOT present.
I (5029) pd stsafe utils: Product Data Query
I (5029) pd stsafe intf: BusSend (4 bytes)
I (5029) pd stsafe intf: TimeDelay (5ms)
I (5039) pd stsafe intf: BusRecv (44 bytes)
I (5059) pd stsafe intf: BusRecv (69 bytes)
StSafeA110 Product Data:
  MaskIdentification: 0xaa4602
  STNumber: 0xa00f0059e439520139
I (5079) pd stsafe utils: Echo Hello
I (5079) pd stsafe intf: BusSend (9 bytes)
I (5089) pd stsafe intf: TimeDelay (5ms)
I (5089) pd stsafe intf: BusRecv (11 bytes)
I (5099) pd stsafe utils: Query Data Zones
I (5099) pd stsafe intf: BusSend (4 bytes)
I (5099) pd stsafe intf: TimeDelay (5ms)
I (5109) pd stsafe intf: BusRecv (6 bytes)
I (5109) pd stsafe intf: BusRecv (54 bytes)
I (5129) pd stsafe utils: DataZones (bytes): 1000,700,600,600,1696,64(owc),64(owc),1578
I (5129) pd stsafe: init complete
E (5129) pd main: usb_serial_jtag_is_connected() 1
I (5129) pd genuine: running check
I (5139) pd self test suite: running security test suite
I (5139) pd self test suite: ---- test:    stsafe-challenge ----
I (5139) pd self test: Issued PEM (669 bytes): 
-----BEGIN CERTIFICATE-----
MIIBwDCCAWegAwIBAgIQEnxq/2MmF+zsmhK9oYMTUDAKBggqhkjOPQQDAjA2MRYw
FAYDVQQKDA1KYW1jb3JkZXIsTExDMRwwGgYDVQQLDBNKYW1jb3JkZXItU3RTYWZl
LUNBMCAXDTI0MDYyMTExNTcwNFoYDzI1MjQwMjIxMTE1NzA0WjBJMRYwFAYDVQQK
DA1KYW1jb3JkZXIsTExDMSAwHgYDVQQDDBdKYW1jb3JkZXItU3RTYWZlLUlzc3Vl
ZDENMAsGA1UECwwEQXV0aDBZMBMGByqGSM49AgEGCCqGSM49AwEHA0IABFID+2lj
5368f5fwzb6seRAy0fI8+VBYX7WNTdnXjpcD2BusLUh+gDwQrZNtogzvlre817IV
hQ6CizZWkPqodcejQjBAMB0GA1UdDgQWBBQ5r/1OYyo/Uc6IrbZc9/8ssrv3FTAf
BgNVHSMEGDAWgBSz9lvn97tzkG9lKiDsSi1HTiNBpDAKBggqhkjOPQQDAgNHADBE
AiBZp5sjUOQAVkObcosT8925emS6qWAcOP2tJ0Fxb6tGrQIgUFXlfQfBFGTvjLv3
4R1ndrBTkE6DAnrf2ChSiO705uI=
-----END CERTIFICATE-----

I (5159) pd self test: mbedtls: parse pem
I (5159) pd self test: mbedtls: parse der issued cert
I (5159) pd self test: mbedtls: parse public key (91 bytes)
X : 5203FB6963E77EBC7F97F0CDBEAC791032D1F23CF950585FB58D4DD9D78E9703
Y : D81BAC2D487E803C10AD936DA20CEF96B7BCD7B215850E828B365690FAA875C7
Z : 01
I (5159) pd self test: esp ds: create signature
I (5169) pd stsafe utils: Generate Signature
I (5169) pd stsafe intf: BusSend (38 bytes)
I (5179) pd stsafe intf: TimeDelay (120ms)
I (5299) pd stsafe intf: BusRecv (73 bytes)
I (5319) pd stsafe intf: BusSend (38 bytes)
I (5339) pd stsafe intf: TimeDelay (120ms)
I (5459) pd stsafe intf: BusRecv (73 bytes)
I (5479) pd stsafe intf: BusSend (38 bytes)
I (5499) pd stsafe intf: TimeDelay (120ms)
I (5619) pd stsafe intf: BusRecv (73 bytes)
I (5639) pd stsafe intf: BusSend (38 bytes)
I (5659) pd stsafe intf: TimeDelay (120ms)
I (5779) pd stsafe intf: BusRecv (73 bytes)
I (5799) pd stsafe intf: BusSend (38 bytes)
I (5819) pd stsafe intf: TimeDelay (120ms)
I (5939) pd stsafe intf: BusRecv (73 bytes)
R : 2C846011B2A658F2E2ECDAE69944C02D0FA4EADBD9D215A5D65D069BE317572E
S : 2B3A2CAFDCDBF7213C1D00C168E766707B3AFADDCD669348BC63214B7E2554F0
I (5959) pd self test: mbedtls: verifying ECDSA signature with public key
I (6119) pd self test: mbedtls: success
I (6119) pd self test suite: ---- success: stsafe-challenge ----
I (6119) pd self test suite: ---- test:    stsafe-verify-preprov-cert ----
I (6119) pd stsafe utils: Read Data Zone 0 (1000 bytes)
offset 0 toTrasfer 504
I (6119) pd stsafe intf: BusSend (9 bytes)
I (6129) pd stsafe intf: TimeDelay (5ms)
I (6129) pd stsafe intf: BusRecv (509 bytes)
offset 504 toTrasfer 496
I (6319) pd stsafe intf: BusSend (9 bytes)
I (6319) pd stsafe intf: TimeDelay (5ms)
I (6329) pd stsafe intf: BusRecv (509 bytes)
Preprov DER: (1000 bytes) 3082018f30820134a003020102020b0209a00f0059e439520139300a06082a8648ce3d040302304f310b3009060355040613024e4c311e301c060355040a0c1553544d6963726f656c656374726f6e696373206e763120301e06035504030c1753544d205354534146452d412050524f442043412030313020170d3230303232363030303030305a180f32303530303232363030303030305a3046310b3009060355040613024652311b3019060355040a0c1253544d6963726f656c656374726f6e696373311a301806035504030c115354534146452d41313130204556414c323059301306072a8648ce3d020106082a8648ce3d030107034200045203fb6963e77ebc7f97f0cdbeac791032d1f23cf950585fb58d4dd9d78e9703d81bac2d487e803c10ad936da20cef96b7bcd7b215850e828b365690faa875c7300a06082a8648ce3d040302034900304602210088f4fbcd505c77b4f2fa547cea843e54578f960266531bd27722f2995db29296022100bbbdd5098dd3c5161f1629b3ab86b04559d3766ff88495fd98f99c1592bc0fd2000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
I (6559) pd self test: mbedtls: parse der issued cert
I (6559) pd self test: mbedtls: parse public key (91 bytes)
X : 5203FB6963E77EBC7F97F0CDBEAC791032D1F23CF950585FB58D4DD9D78E9703
Y : D81BAC2D487E803C10AD936DA20CEF96B7BCD7B215850E828B365690FAA875C7
Z : 01
I (6569) pd self test: esp ds: create signature
I (6569) pd stsafe utils: Generate Signature
I (6569) pd stsafe intf: BusSend (38 bytes)
I (6579) pd stsafe intf: TimeDelay (120ms)
I (6699) pd stsafe intf: BusRecv (73 bytes)
I (6719) pd stsafe intf: BusSend (38 bytes)
I (6739) pd stsafe intf: TimeDelay (120ms)
I (6859) pd stsafe intf: BusRecv (73 bytes)
I (6879) pd stsafe intf: BusSend (38 bytes)
I (6899) pd stsafe intf: TimeDelay (120ms)
I (7019) pd stsafe intf: BusRecv (73 bytes)
I (7039) pd stsafe intf: BusSend (38 bytes)
I (7059) pd stsafe intf: TimeDelay (120ms)
I (7179) pd stsafe intf: BusRecv (73 bytes)
I (7199) pd stsafe intf: BusSend (38 bytes)
I (7219) pd stsafe intf: TimeDelay (120ms)
I (7339) pd stsafe intf: BusRecv (73 bytes)
R : 119BE3D076DDCD2733E3B72515A8D168BE7A4CD5974A5759AC474A7BC7B3611F
S : DB58D0B34BB9893DFE544B915BF98A225DB2DE590B13A5FAACF841F96543AA8D
I (7359) pd self test: mbedtls: verifying ECDSA signature with public key
I (7519) pd self test: mbedtls: success
I (7519) pd self test suite: ---- success: stsafe-verify-preprov-cert ----
I (7519) pd self test suite: ---- test:    stsafe-verify-issued-cert ----
I (7519) pd self test: Issued PEM (669 bytes): 
-----BEGIN CERTIFICATE-----
MIIBwDCCAWegAwIBAgIQEnxq/2MmF+zsmhK9oYMTUDAKBggqhkjOPQQDAjA2MRYw
FAYDVQQKDA1KYW1jb3JkZXIsTExDMRwwGgYDVQQLDBNKYW1jb3JkZXItU3RTYWZl
LUNBMCAXDTI0MDYyMTExNTcwNFoYDzI1MjQwMjIxMTE1NzA0WjBJMRYwFAYDVQQK
DA1KYW1jb3JkZXIsTExDMSAwHgYDVQQDDBdKYW1jb3JkZXItU3RTYWZlLUlzc3Vl
ZDENMAsGA1UECwwEQXV0aDBZMBMGByqGSM49AgEGCCqGSM49AwEHA0IABFID+2lj
5368f5fwzb6seRAy0fI8+VBYX7WNTdnXjpcD2BusLUh+gDwQrZNtogzvlre817IV
hQ6CizZWkPqodcejQjBAMB0GA1UdDgQWBBQ5r/1OYyo/Uc6IrbZc9/8ssrv3FTAf
BgNVHSMEGDAWgBSz9lvn97tzkG9lKiDsSi1HTiNBpDAKBggqhkjOPQQDAgNHADBE
AiBZp5sjUOQAVkObcosT8925emS6qWAcOP2tJ0Fxb6tGrQIgUFXlfQfBFGTvjLv3
4R1ndrBTkE6DAnrf2ChSiO705uI=
-----END CERTIFICATE-----

I (7539) pd self test: CA PEM (673 bytes): 
-----BEGIN CERTIFICATE-----
MIIBwzCCAWmgAwIBAgIUfZexZDXfqbDNz7lSsbw0H8zDtaAwCgYIKoZIzj0EAwIw
NjEWMBQGA1UECgwNSmFtY29yZGVyLExMQzEcMBoGA1UECwwTSmFtY29yZGVyLVN0
U2FmZS1DQTAgFw0yNDAyMjgwNDA3MjdaGA8zMDIzMDcwMTA0MDcyN1owNjEWMBQG
A1UECgwNSmFtY29yZGVyLExMQzEcMBoGA1UECwwTSmFtY29yZGVyLVN0U2FmZS1D
QTBZMBMGByqGSM49AgEGCCqGSM49AwEHA0IABFwlHoaJJVrJuoMQSivV7fHptpAt
XBVO+yeanJA+FekwKhECqqZTNjUkwSlLZuQUYZ2+F82hRQG9RLA+gDrmUPajUzBR
MB0GA1UdDgQWBBSz9lvn97tzkG9lKiDsSi1HTiNBpDAfBgNVHSMEGDAWgBSz9lvn
97tzkG9lKiDsSi1HTiNBpDAPBgNVHRMBAf8EBTADAQH/MAoGCCqGSM49BAMCA0gA
MEUCIQD6kuncnr8NxLZUIuZpkmxT6IqaPDdzQFGgRn3qXywQxAIgTxhbwpevK9Hn
/NZQ7z5AYjBdgimvcJFogCUU1rn/Jrc=
-----END CERTIFICATE-----

I (7549) pd self test: mbedtls: parse issued pem
I (7559) pd self test: mbedtls: parse ca pem
I (7559) pd self test: mbedtls: verifying ca cert...
I (7709) pd self test: mbedtls: success
I (7719) pd self test suite: ---- success: stsafe-verify-issued-cert ----
I (7719) pd self test suite: ---- test:    stsafe-verify-ca-cert ----
I (7719) pd self test: CA PEM (673 bytes): 
-----BEGIN CERTIFICATE-----
MIIBwzCCAWmgAwIBAgIUfZexZDXfqbDNz7lSsbw0H8zDtaAwCgYIKoZIzj0EAwIw
NjEWMBQGA1UECgwNSmFtY29yZGVyLExMQzEcMBoGA1UECwwTSmFtY29yZGVyLVN0
U2FmZS1DQTAgFw0yNDAyMjgwNDA3MjdaGA8zMDIzMDcwMTA0MDcyN1owNjEWMBQG
A1UECgwNSmFtY29yZGVyLExMQzEcMBoGA1UECwwTSmFtY29yZGVyLVN0U2FmZS1D
QTBZMBMGByqGSM49AgEGCCqGSM49AwEHA0IABFwlHoaJJVrJuoMQSivV7fHptpAt
XBVO+yeanJA+FekwKhECqqZTNjUkwSlLZuQUYZ2+F82hRQG9RLA+gDrmUPajUzBR
MB0GA1UdDgQWBBSz9lvn97tzkG9lKiDsSi1HTiNBpDAfBgNVHSMEGDAWgBSz9lvn
97tzkG9lKiDsSi1HTiNBpDAPBgNVHRMBAf8EBTADAQH/MAoGCCqGSM49BAMCA0gA
MEUCIQD6kuncnr8NxLZUIuZpkmxT6IqaPDdzQFGgRn3qXywQxAIgTxhbwpevK9Hn
/NZQ7z5AYjBdgimvcJFogCUU1rn/Jrc=
-----END CERTIFICATE-----

I (7729) pd self test: mbedtls: parse ca pem
I (7739) pd self test: mbedtls: verifying ca cert...
I (7739) pd self test: mbedtls: parse public key (91 bytes)
X : 5C251E8689255AC9BA83104A2BD5EDF1E9B6902D5C154EFB279A9C903E15E930
Y : 2A1102AAA653363524C1294B66E414619DBE17CDA14501BD44B03E803AE650F6
Z : 01
I (7739) pd self test: mbedtls: success
I (7739) pd self test suite: ---- success: stsafe-verify-ca-cert ----
I (7749) pd genuine: Genuine!
E (7749) pd main: usb_serial_jtag_is_connected() 1
I (7749) pd lifestats: init
I (7749) pd time ram: reading ram
W (7759) pd time ram: invalid ram version. expected 4, found 59. using 0.
millisPlayedA 0
millisPlayedB 0
notesPlayedA 0
notesPlayedB 0
W (7759) pd lifestats: LifeStats JSON not found
I (7759) pd lifestats: rtcStats:   millisPlayed 0, notesPlayed 0
I (7759) pd lifestats: flashStats: millisPlayed 0, notesPlayed 0
I (7769) pd lifestats: rtcStats == flashStats. Good.
I (7769) pd lifestats: Notes  Played: 0
I (7769) pd lifestats: Millis Played: 0
I (7769) pd lifestats: Commit Count: 0
E (7769) pd main: usb_serial_jtag_is_connected() 1
I (7769) pd sd card: Init
I (7769) pd sd card: configuring GPIO SD Card Detect
I (7769) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 
E (7779) pd main: usb_serial_jtag_is_connected() 1
E (7779) pd main: usb_serial_jtag_is_connected() 1
I (7779) pd api init: pd_api_init() called
I (7779) pd api: allocating API list
I (7779) pd api: register [0] /
I (7779) pd api: register [1] /favicon.ico
I (7779) pd api: register [2] /api/meta/capabilities
I (7779) pd api: register [3] /api/meta/endpoints
I (7789) pd api: register [4] /api/fab-info/capabilities
I (7789) pd api: register [5] /api/fab-info/get
I (7789) pd api: register [6] /api/fab-info/set
I (7789) pd api: register [7] /api/logs/capabilities
I (7789) pd api: register [8] /logs
I (7789) pd api: register [9] /api/logs/websocket
I (7789) pd api: register [10] /api/logs/websocket
I (7799) pd api: register [11] /api/logs/websocket
I (7799) pd api: register [12] /api/logs/recent/logs
I (7799) pd api: register [13] /api/logs/recent/errors
I (7799) pd api: register [14] /api/logs/recent/warnings
I (7799) pd api: register [15] /api/logs/recent/generic
I (7799) pd api: register [16] /api/verbose/capabilities
I (7799) pd api: register [17] /api/verbose/debug/list
I (7809) pd api: register [18] /api/verbose/debug/state
I (7809) pd api: register [19] /api/verbose/debug/enable
I (7809) pd api: register [20] /api/verbose/debug/disable
I (7809) pd api: register [21] /api/verbose/debug/firehose
I (7809) pd api: register [22] /api/verbose/debug/clear
I (7809) pd api: register [23] /api/verbose/debug/persist
I (7809) pd api: register [24] /api/verbose/debug/unpersist
I (7819) pd api: register [25] /api/coredump/capabilities
I (7819) pd api: register [26] /api/coredump/download
I (7819) pd api: register [27] /api/coredump/summary
I (7819) pd api: register [28] /api/system/capabilities
I (7819) pd api: register [29] /api/system/software-info
I (7819) pd api: register [30] /api/system/cpu-info
I (7819) pd api: register [31] /api/system/reboot
I (7829) pd api: register [32] /api/system/is-alive
I (7829) pd api: register [33] /api/ota/capabilities
I (7829) pd api: register [34] /api/ota/overview
I (7829) pd api: register [35] /api/ota/jfu/boot-args/get
I (7829) pd api: register [36] /api/ota/jfu/boot-args/set
I (7829) pd api: register [37] /api/ota/jfu/boot-args/clear
I (7829) pd api: register [38] /api/ota/jfu/reboot-into
I (7839) pd api: register [39] /api/ota/sd/upload/simple
I (7839) pd api: register [40] /api/ota/sd/firmware/available
I (7839) pd api: register [41] /api/ota/sd/install/simple
I (7839) pd api: register [42] /api/ota/direct/install/simple
I (7839) pd api: register [43] /api/ota/resumable/install/progress
I (7839) pd api: register [44] /api/ota/resumable/install/upload-chunk
I (7849) pd api: register [45] /api/issues/capabilities
I (7849) pd api: register [46] /api/issues/current
I (7849) pd api: register [47] /api/issues/history
I (7849) pd api: register [48] /api/issues/clear/current
I (7849) pd api: register [49] /api/factory-reset/capabilities
I (7849) pd api: register [50] /api/factory-reset/all
I (7849) pd api: register [51] /api/factory-reset/choose
I (7859) pd api: register [52] /api/self-test/capabilities
I (7859) pd api: register [53] /api/self-test/list
I (7859) pd api: register [54] /api/self-test/run/single-test
I (7859) pd api: register [55] /api/self-test/run/factory-test-suite
I (7859) pd api: register [56] /webapp
I (7859) pd api: register [57] /webapp/*
I (7859) pd api: register [58] /sdcard/?*
I (7869) pd api: register [59] /api/identities/capabilities
I (7869) pd api: register [60] /api/identities/get
I (7869) pd api: register [61] /api/identities/rename/jamcorder
I (7869) pd api: register [62] /api/identities/rename/performer
I (7869) pd api: register [63] /api/device-state/capabilities
I (7869) pd api: register [64] /api/device-state/get
I (7879) pd api: register [65] /api/time/capabilities
I (7879) pd api: register [66] /api/time/get
I (7879) pd api: register [67] /api/time/set
I (7879) pd api: register [68] /api/time/sntp/disable
I (7879) pd api: register [69] /api/time/sntp/enable
I (7879) pd api: register [70] /api/time/debug/guess-time-from-sdcard
I (7879) pd api: register [71] /api/wifi/capabilities
I (7889) pd api: register [72] /api/wifi/info
I (7889) pd api: register [73] /api/wifi/credentials/set
I (7889) pd api: register [74] /api/wifi/credentials/clear
I (7889) pd api: register [75] /api/wifi/scan/simple
I (7889) pd api: register [76] /api/usb/capabilities
I (7889) pd api: register [77] /api/usb/state
I (7889) pd api: register [78] /api/usb/descriptors
I (7889) pd api: register [79] /api/sdcard/capabilities
I (7899) pd api: register [80] /api/sdcard/format-fix/simple
I (7899) pd api: register [81] /api/sdcard/info
I (7899) pd api: register [82] /api/sdcard/free-bytes/simple
I (7899) pd api: register [83] /api/sdcard/debug/details
I (7899) pd api: register [84] /api/files/capabilities
I (7899) pd api: register [85] /api/files/list/overview
I (7909) pd api: register [86] /api/files/list/detailed
I (7909) pd api: register [87] /api/files/download/simple
I (7909) pd api: register [88] /api/files/download/offset
I (7909) pd api: register [89] /api/files/upload/simple
I (7909) pd api: register [90] /api/piano/capabilities
I (7909) pd api: register [91] /api/piano/state
I (7909) pd api: register [92] /api/library/capabilities
I (7919) pd api: register [93] /api/library/download/newest/midi
I (7919) pd api: register [94] /api/library/list/assets
I (7919) pd api: register [95] /api/library/list/years
I (7919) pd api: register [96] /api/asset/debug/next-header
I (7919) pd api: register [97] /api/asset/debug/eof-summary
I (7919) pd api: register [98] /api/buzzer/capabilities
I (7919) pd api: register [99] /api/buzzer/settings/set
I (7929) pd api: register [100] /api/buzzer/settings/get
I (7929) pd api: register [101] /api/midi-cmd/capabilities
I (7929) pd api: register [102] /api/midi-cmd/bookmark
I (7929) pd api: register [103] /api/midi-cmd/settings/get
I (7929) pd api: register [104] /api/midi-cmd/settings/set
I (7929) pd api: register [105] /api/midi-tests/debug/triad-out
I (7939) pd api: register [106] /api/midi-tests/debug/triad-in
I (7939) pd api: register [107] /api/midi-tests/debug/complex-in
I (7939) pd api: register [108] /api/midi-tests/debug/complex-out
I (7939) pd api: register [109] /api/midi-recorder/capabilities
I (7939) pd api: register [110] /api/midi-recorder/settings/get
I (7939) pd api: register [111] /api/midi-recorder/settings/set
I (7949) pd api: register [112] /api/midi-io/capabilities
I (7949) pd api: register [113] /api/midi-io/msg-counts
I (7949) pd api: register [114] /api/midi-io/active-converters
I (7949) pd api: register [115] /api/midi-io/websocket
I (7949) pd api: register [116] /api/midi-io/websocket
I (7949) pd api: register [117] /api/midi-io/websocket
I (7949) pd api: register [118] /api/midi-stones/download/stone
I (7959) pd api: register [119] /api/midi-stones/stream
I (7959) pd api: register [120] /api/midi-stones/stream
I (7959) pd api: register [121] /api/midi-stones/stream
I (7959) pd api: register [122] /api/lifestats/capabilities
I (7959) pd api: register [123] /api/lifestats/get
I (7959) pd api: register [124] /api/lifestats/clear
I (7959) pd api: register [125] /api/extensions/capabilities
I (7969) pd api: register [126] /extensions/*
I (7969) pd api: register [127] /api/extensions/list
I (7969) pd api: register [128] /api/extensions/upload-install-html
I (7969) pd api: register [129] /api/extensions/upload-install-tar
I (7969) pd api: register [130] /api/extensions/uninstall
I (7969) pd api: register [131] /api/nvs/debug/list
I (7979) pd api: register [132] /api/nvs/debug/set
I (7979) pd api: register [133] /test-pages/websocket-midi-live-stream
I (7979) pd api: register [134] /test-pages/websocket-midi-stone-stream
I (7979) pd api: register [135] /test-pages/websocket-alerts
I (7979) pd api: register [136] /test-pages/ble-info
I (7979) pd api: register [137] /test-pages/ble-http
I (7979) pd api: register [138] /test-pages/ble-midi-stone-steam
I (7989) pd api: register [139] /test-pages/ble-alerts
I (7989) pd api: register [140] /test-pages/ota
I (7989) pd api: register [141] /api/discovery-mode/capabilities
I (7989) pd api: register [142] /api/discovery-mode/enter
I (7989) pd api: register [143] /api/stsafe/capabilities
I (7989) pd api: register [144] /api/stsafe/ca-cert-pem
I (7999) pd api: register [145] /api/stsafe/issued-cert-pem
I (7999) pd api: register [146] /api/stsafe/challenge
I (7999) pd api: register [147] /api/stsafe/bulk-challenge/simple
I (7999) pd api: register [148] /api/stsafe/print-all-zone-bytes
I (7999) pd api: register [149] /api/factory-mode/capabilities
I (7999) pd api: register [150] /api/factory-mode/unlock
I (7999) pd api: register [151] /api/factory-mode/stsafe/preprov-cert-der
I (8009) pd api: register [152] /api/factory-mode/stsafe/upload-issued-cert-pem
I (8009) pd api: register [153] /api/factory-mode/stsafe/upload-ca-cert-pem
I (8009) pd api: register [154] /api/debug/force-system-crash
I (8009) pd api: register [155] /api/debug/freertos-tasks
I (8009) pd api: register [156] /api/debug/partition-table
I (8019) pd api: register [157] /api/debug/efuses/list
I (8019) pd api: register [158] /api/debug/efuses/raw
I (8019) pd api: register [159] /api/heap/debug/free-bytes
I (8019) pd api: register [160] /api/heap/debug/alloc-stats
I (8019) pd api: register [161] /api/heap/debug/check-integrity
I (8019) pd api: register [162] /api/heap-trace/debug/start-all
I (8019) pd api: register [163] /api/heap-trace/debug/start-leaks
I (8029) pd api: register [164] /api/heap-trace/debug/pause
I (8029) pd api: register [165] /api/heap-trace/debug/resume
I (8029) pd api: register [166] /api/heap-trace/debug/dump/all
I (8029) pd api: register [167] /api/heap-trace/debug/dump/internal
I (8029) pd api: register [168] /api/heap-trace/debug/dump/spi
I (8029) pd api: register [169] /api/heap-trace/debug/summary
I (8039) pd api: register [170] /api/bluetooth/capabilities
I (8039) pd api: register [171] /api/bluetooth/state/get
I (8039) pd api: register [172] /api/bluetooth/state/detailed
I (8039) pd api: register [173] /api/alerts/capabilities
I (8039) pd api: register [174] /api/alerts/recent
I (8039) pd api: register [175] /api/alerts/websocket
I (8049) pd api: register [176] /api/alerts/websocket
I (8049) pd api: register [177] /api/alerts/websocket
I (8049) pd api: register [178] /api/developer/capabilities
I (8049) pd api: register [179] /api/developer/settings
I (8049) pd api: register [180] /api/developer/mode/enable
I (8049) pd api: register [181] /api/developer/mode/disable
I (8049) pd api: register [182] /api/developer/cmd/list
I (8059) pd api: register [183] /api/developer/cmd/set
I (8059) pd api: register [184] /api/developer/cmd/unset
I (8059) pd api: register [185] /api/developer/reset-all
I (8059) pd api: register [186] /internal
I (8059) pd api: register [187] /docs/extensions
I (8059) pd api: register [188] /jfu
I (8059) pd api init: API Count 189
E (8059) pd main: usb_serial_jtag_is_connected() 1
W (8069) pd main: wifi: not configured. leaving off
E (8069) pd main: usb_serial_jtag_is_connected() 1
I (8069) pd console: init
I (8069) pd console: registering 189uris
E (8119) pd main: usb_serial_jtag_is_connected() 1
I (8119) pd bt jmxinfo: init
I (8119) pd bt midi: init
I (8119) pd bt midi in: init
I (8119) pd bt midi out: init
I (8119) pd bt midi out: xTaskCreate midi_bt_tx_task
I (8119) pd bt midi out: allocate msg queue: 44000 bytes
I (8129) pd bt midi out: Bluetooth OUT task started
I (8129) pd bthttp: init
I (8159) pd bthttp: xTaskCreate btApiTask
I (8159) pd bthttp: btApiTask started
I (8159) pd mf stream bt: init
I (8159) pd ble: init
I (8159) BLE_INIT: BT controller compile version [30b57c4]
I (8169) BLE_INIT: Bluetooth MAC: 10:36:61:63:33:38

I (8169) phy_init: phy_version 670,b7bc9b9,Apr 30 2024,10:54:13
I (8209) pd ble: ble device name: jam-96a
I (8209) pd ble: Start Nimble Port Run
I (8209) pd ble: GATT registered service:
I (8219) pd ble:    uuid: 0x1800
I (8219) pd ble:    svc: GAP Svc
I (8219) pd ble:    handle: 1
I (8219) pd ble: GATT registered characteristic:
I (8219) pd ble:    uuid: 0x2a00
I (8219) pd ble:    chr: GAP Device Name Chr
I (8219) pd ble:    defHandle: 2
I (8219) pd ble:    valHandle: 3
I (8219) pd ble: GATT registered characteristic:
I (8219) pd ble:    uuid: 0x2a01
I (8219) pd ble:    chr: GAP Appearance Chr
I (8229) pd ble:    defHandle: 4
I (8229) pd ble:    valHandle: 5
I (8229) pd ble: GATT registered service:
I (8229) pd ble:    uuid: 0x1801
I (8229) pd ble:    svc: GATT Svc
I (8229) pd ble:    handle: 6
I (8229) pd ble: GATT registered characteristic:
I (8229) pd ble:    uuid: 0x2a05
I (8229) pd ble:    chr: GATT Service Changed Chr
I (8239) pd ble:    defHandle: 7
I (8239) pd ble:    valHandle: 8
I (8239) pd ble: GATT registered characteristic:
I (8239) pd ble:    uuid: 0x2b3a
I (8239) pd ble:    chr: Server Supported Features
I (8239) pd ble:    defHandle: 10
I (8239) pd ble:    valHandle: 11
I (8239) pd ble: GATT registered characteristic:
I (8239) pd ble:    uuid: 0x2b29
I (8239) pd ble:    chr: Client Supported Features
I (8249) pd ble:    defHandle: 12
I (8249) pd ble:    valHandle: 13
I (8249) pd ble: GATT registered service:
I (8249) pd ble:    uuid: 68190001-79e5-4143-8f1d-2f9f09027306
I (8249) pd ble:    svc: Jmx Info
I (8249) pd ble:    handle: 14
I (8249) pd ble: GATT registered characteristic:
I (8249) pd ble:    uuid: 68190002-79e5-4143-8f1d-2f9f09027306
I (8259) pd ble:    chr: Jmx Info - Execute Command
I (8259) pd ble:    defHandle: 15
I (8259) pd ble:    valHandle: 16
I (8259) pd ble: GATT registered characteristic:
I (8259) pd ble:    uuid: 68190003-79e5-4143-8f1d-2f9f09027306
I (8259) pd ble:    chr: Jmx Info - Jamcorder UUID
I (8259) pd ble:    defHandle: 17
I (8259) pd ble:    valHandle: 18
I (8269) pd ble: GATT registered characteristic:
I (8269) pd ble:    uuid: 68190004-79e5-4143-8f1d-2f9f09027306
I (8269) pd ble:    chr: Jmx Info - Running App Name
I (8269) pd ble:    defHandle: 19
I (8269) pd ble:    valHandle: 20
I (8269) pd ble: GATT registered characteristic:
I (8269) pd ble:    uuid: 68190005-79e5-4143-8f1d-2f9f09027306
I (8279) pd ble:    chr: Jmx Info - Running Partition Label
I (8279) pd ble:    defHandle: 21
I (8279) pd ble:    valHandle: 22
I (8279) pd ble: GATT registered characteristic:
I (8279) pd ble:    uuid: 68190006-79e5-4143-8f1d-2f9f09027306
I (8279) pd ble:    chr: Jmx Info - Jfwm Sha256
I (8279) pd ble:    defHandle: 23
I (8279) pd ble:    valHandle: 24
I (8279) pd ble: GATT registered characteristic:
I (8289) pd ble:    uuid: 68190007-79e5-4143-8f1d-2f9f09027306
I (8289) pd ble:    chr: Jmx Info - Jfwm Version
I (8289) pd ble:    defHandle: 25
I (8289) pd ble:    valHandle: 26
I (8289) pd ble: GATT registered characteristic:
I (8289) pd ble:    uuid: 68190008-79e5-4143-8f1d-2f9f09027306
I (8289) pd ble:    chr: Jmx Info - Jfu Sha256
I (8299) pd ble:    defHandle: 27
I (8299) pd ble:    valHandle: 28
I (8299) pd ble: GATT registered characteristic:
I (8299) pd ble:    uuid: 68190009-79e5-4143-8f1d-2f9f09027306
I (8299) pd ble:    chr: Jmx Info - Jfu Version
I (8299) pd ble:    defHandle: 29
I (8299) pd ble:    valHandle: 30
I (8299) pd ble: GATT registered service:
I (8299) pd ble:    uuid: 02aa0001-4202-649d-ec11-dfdb58e9372d
I (8309) pd ble:    svc: Jmx BtHttp Svc
I (8309) pd ble:    handle: 31
I (8309) pd ble: GATT registered characteristic:
I (8309) pd ble:    uuid: 02aa0002-4202-649d-ec11-dfdb58e9372d
I (8309) pd ble:    chr: Jmx BtHttp Chr
I (8309) pd ble:    defHandle: 32
I (8309) pd ble:    valHandle: 33
I (8309) pd ble: GATT registered service:
I (8319) pd ble:    uuid: cf5d0001-6fcc-47b3-80af-1aafcf967f32
I (8319) pd ble:    svc: Jmx Midi Stone Stream Svc
I (8319) pd ble:    handle: 35
I (8319) pd ble: GATT registered characteristic:
I (8319) pd ble:    uuid: cf5d0002-6fcc-47b3-80af-1aafcf967f32
I (8319) pd ble:    chr: Jmx Midi Stone Stream Chr
I (8319) pd ble:    defHandle: 36
I (8319) pd ble:    valHandle: 37
I (8329) pd ble: GATT registered service:
I (8329) pd ble:    uuid: a6510001-dc93-42ac-a3cf-fd1efe6d148d
I (8329) pd ble:    svc: Jmx Alerts Svc
I (8329) pd ble:    handle: 39
I (8329) pd ble: GATT registered characteristic:
I (8329) pd ble:    uuid: a6510002-dc93-42ac-a3cf-fd1efe6d148d
I (8329) pd ble:    chr: Jmx Alerts Chr
I (8329) pd ble:    defHandle: 40
I (8339) pd ble:    valHandle: 41
I (8339) pd ble: GATT registered service:
I (8339) pd ble:    uuid: 03b80e5a-ede8-4b33-a751-6ce34ec4c700
I (8339) pd ble:    svc: Ble Midi Svc
I (8339) pd ble:    handle: 43
I (8339) pd ble: GATT registered characteristic:
I (8339) pd ble:    uuid: 7772e5db-3868-4112-a1a9-f2669d106bf3
I (8339) pd ble:    chr: Ble Midi
I (8349) pd ble:    defHandle: 44
I (8349) pd ble:    valHandle: 45
I (8349) NimBLE: GAP procedure initiated: stop advertising.

I (8349) pd ble: on_ble_sync_handler() called
I (8349) pd ble: ownAddrType: Public
I (8349) pd ble: Device Address: 10:36:61:63:33:38
I (8349) pd ble: ***** start advertising *****
I (8359) NimBLE: GAP procedure initiated: advertise; 
I (8359) NimBLE: disc_mode=2
I (8359) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
I (8359) NimBLE: 

I (8359) pd ble: Set BLE TX Power Level: +6dbm (default)
I (8359) pd ble: Set BLE Tx Power Level: +6bm (advertise)
E (8359) pd main: usb_serial_jtag_is_connected() 1
I (8369) pd midi pipeline: init
I (8369) pd midi passthrough: init
I (8369) pd midi pipeline: allocate msg queue: 216000 bytes
I (8459) pd midi pipeline: xTaskCreate midi_pipeline_task
I (8459) pd midi pipeline: pipeline task started
E (8459) pd main: usb_serial_jtag_is_connected() 1
I (8459) pd uart midi: init
I (8459) uart: queue free spaces: 100
I (8459) pd uart midi in: init
I (8459) pd uart midi in: xTaskCreate midi_uart_rx_task
I (8459) pd uart midi in: rx task loop
I (8459) pd uart midi out: init
I (8459) pd uart midi out: allocate msg queue: 44000 bytes
I (8479) pd uart midi out: xTaskCreate midi_uart_tx_task
I (8479) pd uart midi out: UART OUT task started
E (8479) pd main: usb_serial_jtag_is_connected() 1
I (8479) pd mss: init
I (8479) pd mss: xTaskCreate mss
I (8479) pd mss: stream_file_loop started
E (8499) pd main: usb_serial_jtag_is_connected() 0
I (8499) pd midi usb: init
I (8499) pd midi usb: xTaskCreate midi_usb_open_loop
I (8499) pd main: Wait for usb midi to init...
I (8499) pd midi usb: midi_usb_open_loop task started
I (8499) pd usbh: oneTimeInit()
I (8509) pd usbh: [oneTimeInit] create xUsbhInitializeMutex
I (8509) pd usbh: [oneTimeInit] create xOpenedDeviceHandlesMutex
I (8509) pd usbh: [oneTimeInit] create queue xDeviceConnectedEvents
I (9479) pd mss: all clients up to date. sleeping
semaphore: 0

chipweinberger avatar Aug 21 '24 22:08 chipweinberger

@chipweinberger If you increase the value here, does it help you?

🎉🎉🎉🎉

Yes. I tried a value of 15 instead of 3, and it worked!

I have not tried other values.

chipweinberger avatar Aug 21 '24 22:08 chipweinberger

Yah, I guess the default tolerance ALLOWED_NO_SOF_TICKS was not enough for your application, maybe due to too many modules are involved, and led to a big delay in handling the FreeRTOS tick interrupts. The value of USJ_DISCONNECT_CONFIRM_PERIOD_MS can be increased as you want, just to notice that the larger the value is, the longer it takes to confirm a real disconnection.

songruo avatar Aug 22 '24 08:08 songruo

please make the value configurable, without forking ESP-IDF :)

and you should probably increase the default value too, so that it works by default. 15ms delay is fine.

chipweinberger avatar Aug 22 '24 13:08 chipweinberger

After calling nvs_flash_init(), usb_serial_jtag_is_connected() returns false, whereas before calling nvs_flash_init(), usb_serial_jtag_is_connected() returns true. I'm using an esp32-s3 platform, esp-idf 5.2.1, setting ALLOWED_NO_SOF_TICKS to 15.

richlegrand avatar Sep 23 '24 21:09 richlegrand