USB Console stops logging when primary console (IDFGH-6454)

[mdelete]

Environment

• Development Kit: ESP32-C3-DevKit-M-1
• Kit version (for WroverKit/PicoKit/DevKitC): N/A
• Module or chip used: ESP32-C3-MINI-1
• IDF version v5.0-dev-741-g1c82e6eac7
• Build System: idf.py
• Compiler version: riscv32-esp-elf-gcc (crosstool-NG esp-2021r2) 8.4.0
• Operating System: macOS
• (Windows only) environment type: N/A
• Using an IDE?: No
• Power Supply: USB

Problem Description

If you set Component config > ESP System Settings > Channel for console output to USB Serial / JTAG Controller (in which case Channel for console secondary output is forced to no secondary console) then no ESP_LOG output from an app will be printed on the USB console. An app is running fine, though.

In fact the last log output line seen on the USB console will be:

I (376) heap_init: At 50000010 len 00001FF0 (7 KiB): RTCRAM

If you set Channel for console output to Default: UART0 and secondary console to USB_SERIAL_JTAG_CONTROLLER then ESP_LOG output of an app will be visible on both consoles and the system log will not stop early:

I (376) heap_init: At 50000010 len 00001FF0 (7 KiB): RTCRAM
I (383) spi_flash: detected chip: generic
...

Expected Behavior

The JTAG/serial console logs.

Actual Behavior

The JTAG/serial console stops logging early in the startup.

Steps to reproduce

1. Build, flash and run esp-idf/examples/wifi/getting_started/hello_world example without any modification.
2. Use idf.py menuconfig and set (primary) console output to USB Serial / JTAG Controller.
3. Build, flash and run esp-idf/examples/wifi/getting_started/hello_world again you will see logging stop early on.

Code to reproduce this issue

[N/A]

Debug Logs

[N/A]

[esp-wzh]

Hi, @mdelete,
  I don't think it's a bug, IDF's bootloader uses ESP_EARLY_LOGx to print information. After entering the APP and initializing the console, it will switch to use ESP_LOGx to print information. That is, the print you see after I (376) heap_init: At 50000010 len 00001FF0 (7 KiB): RTCRAM
  ESP_EARLY_LOGx is not affected by the configuration in IDF menuconfig, and will print to UART0 and USB-Serial-JTAG at the same time, while ESP_LOGx will only print to the port specified in menuconfig.

[mdelete]

But that's the thing: In my setup ESP_LOGx doesn't log on USB Serial even if I set it to be the primary output. I'll re-test on my side to be sure...

[esp-wzh]

@mdelete, Can you confirm that the USB Serial you monitored is the port of ESP32C3 built-in USB (USB-Serial-JTAG) instead of the port of UART-USB conversion chip?

[mdelete]

I retested it several times and the result is as originally reported: If I enable USB-Serial/JTAG as primary console (which sets secondary console to none) the last line both serial ports (USB-Serial as well as UART with USB-Serial conversion chip) log is:
I (376) heap_init: At 50000010 len 00001FF0 (7 KiB): RTCRAM

[esp-wzh]

Did you connect the hardware according to this documention?
https://docs.espressif.com/projects/esp-idf/en/latest/esp32c3/api-guides/usb-serial-jtag-console.html#hardware-requirements

USB-Serial conversion chip and built-in USB will be shown as different ports on your PC. Like in Ubuntu, the USB-Serial conversion chip shows the port /dev/ttyUSBx and the built-in USB shows the port /dev/ttyACMx, and you should specify the corresponding port to get print

[mythbuster5]

Could you please have a try with the config option CONFIG_USB_SERIAL_JTAG_CONSOLE is on?

[esp-wzh]

@mdelete There are two versions of ESP32-C3-DevKit-M-1, one is that the Micro-USB port on the board is connected to the built-in USB, the other is connected to the USB-Serial conversion chip, the Micro-USB in the picture below is connected to the USB-Serial conversion chip

If remove the two resistors on the left in the red box and jumper them horizontally, you can connect the Micro-USB interface to the built-in USB

This is the print I got on the build-in USB port and USB-Serial port respectively on ESP32-C3-DevKit-M-1 v1.0:

[mdelete]

@esp-wzh My devkit is jumpered as seen in your first picture, I will change that to your suggested setup and retry.
But with the current jumper setup I can already see both serial devices of the devkit at the same time. On macOS it's like this:
/dev/cu.SLAB_USBtoUART (this is a serial port using a silabs driver, so it is the one using the conversion chip)
/dev/cu.usbserial-1440 (this is a serial port using the CDC default driver used by the native USB of the esp32)
I am expecting the latter to show me the correct console, when configuring USB Serial/JTAG as only console, but it doesn't. If configured as primary/secondary both serial devices show a fully working console.

[esp-wzh]

@mdelete How did you connect to get the port /dev/cu.usbserial-1440, I think this is still a UART port, which is the port of the silabs conversion chip on the ESP32-C3-DevKit-M-1 v1.0 development board, The built-in USB port on macos is usually named as /dev/cu.usbmodem*. By the way, you need to use the two resistor jumpers that were removed before.

[mdelete]

I think you're right, I think it is a macOS issue where different drivers claim the same device so this is the silabs chip, but twice. However, if I switch the resistors like you suggested, I also see a serial device, but I can only flash the device, there is no console at all, regardless which setting I chose in menconfig:

ESP-ROM:esp32c3-api1-20210207
Build:Feb  7 2021
rst:0x15 (USB_UART_CHIP_RESET),boot:0x4 (DOWNLOAD(USB/UART0/1))
Saved PC:0x400462e2
waiting for download

[mdelete]

Ha, scratch that. Now it works! Thanks @esp-wzh for you support! I'll test around some more and then eventually close the ticket.