(resolved) can't redirect console output (regression)

[mzimmers]

Hi all -

Earlier this week, I began experimenting with V4.0 of the IDF. It was causing some strange behavior (explained below) so I went back to V3.3, only to discover that the problem seems to persist. I then tried running a hello world example, and the problem occurs there, so at least it's not my application code.

In an attempt to restore a working environment, I've:

1. deleted /esp-idf and re-cloned it from github.
2. deleted the toolchain and re-installed per the instructions on the get started page for V3.3.
3. deleted the app's build directory
4. deleted the app's sdkconfig and regenerated it
5. erased the flash on the board

In short, I don't know what else to do in an attempt to return to a "known" environment. If I've missed a step, I hope someone will tell me.

Now, as for the problem: I'm unable to redirect application output to UART1.

When my menuconfig->component config-> ESP32-specific->UART for console output is set to Default: UART0, TX=GPIO1, RX=GPIO3, and then do a "make flash monitor," my output is fine (including just an excerpt):

Code: Select all

I (256) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (263) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (269) heap_init: At 4008842C len 00017BD4 (94 KiB): IRAM
I (275) cpu_start: Pro cpu start user code
I (294) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
Hello world!
This is ESP32 chip with 2 CPU cores, WiFi/BT/BLE, silicon revision 1, 4MB external flash
Restarting in 10 seconds...
Restarting in 9 seconds...
Restarting in 8 seconds...
Restarting in 7 seconds...

When my menuconfig->component config-> ESP32-specific->UART for console output is set to Custom: UART1, TX= GPIO10, RX=GPIO9,
and do a "make flash," (I don't get any application output. It stops at this line:

I (232) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (239) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (245) heap_init: At 4008842C len 00017BD4 (94 KiB): IRAM
I (251) cpu_start: Pro cpu start user code

And after a little more than 10 seconds (the delay built into the hello world example) it repeats.

SO:

It's as though the application seems to be running fine but it's just not putting out anything to the console. And...this worked fine until I began monkeying with different versions of the IDF. I'm sure I've screwed something up, but as indicated above, I can't think of anything else to restore. Any suggestions?

Thanks...this is driving me absolutely crazy...

[mzimmers]

Not to be too pesky, but...BTT. I'm pretty much out of ideas on this one.

[mzimmers]

As stated above, when I alter the UART settings in menuconfig, I get the bootloader and early startup messages successfully redirected to UART1. Based on this, can I assume that my menuconfig settings are correct, and I should see the hello world output, or is there possibly more at play here?

Thanks.

[WiFive]

Are you using PICO-D4? Do you have psram disabled in menuconfig?

[mzimmers]

Hi WiFive -

I'm using a WROVER. There's no PSRAM entry in my sdkconfig file.

Thanks...

[ESP_Angus]

I'm able to reproduce this with release/v4.0 branch and these settings and also setting flash to DIO mode:

Custom: UART1, TX= GPIO10, RX=GPIO9,

These pins are also known as SD2 and SD3 and are connected to the internal flash chip when using Quad I/O modes. Some fixes for SPI flash performance went into IDF recently, and I think these are causing the pin assignment to be incorrectly changed during startup.

This is a bug and we'll fix it (only can be fixed for DIO & DOUT modes, obviously).

If it's at all possible, you might want to reconsider using these pins at all with a WROVER or WROOM module, as they're still connected to the flash chip inside the WROVER (HOLD# and WP# pins) and they may cause unexpected flash behaviour. We only really guarantee they're safe to repurpose on a custom design which doesn't route them to the flash at all.

[mzimmers]

Hi Angus -

This is great news. It does bring up a couple questions:

1. As I mentioned above, this all came about when I tried to migrate to IDF release/v4.0. When I returned to release/v3.3, however, the problem persisted. I had assumed that the release/v3.3 branch was immutable at this point, but perhaps I was mistaken. If it isn't immutable, which IDF should I use in production?

2. As a follow-up to #1, what IDF release I can I use today to verify that this was the problem?

3. Why am I able to see the bootloader output in my console but not my application output?

4. Oh yeah: when and where can I expect to see the fix? (your comment about use of SD2/3 is noted; I'm forwarding that information to my HW guys)

Finally, I'm impressed by how quickly you found the root cause of this problem. May I ask what development tools you use? My primary complaint about the ESP32 platform is the paucity of modern development tools, notably an interactive debugger. The lack of this has been a major factor in my productivity with this device. (That's why I was trying to move to Eclipse in the first place.)

Thanks so much for all the help on this one.

EDIT: OK, I understand now that my first question suffers from serious lameness. (I'm still new to git and its terminology.) So what I should have asked is, what *tag* should I be using for production at this time?

Also, regarding the use of SD2/SD3: if I'm reading the datasheet correctly, these are my only choices for UART1. I tried using menuconfig to assign some other lines (IO32 and IO35), but I'm not getting any output. Can someone confirm that this is expected behavior?

[mzimmers]

So, a summary on where I am now:

1. I'm building with v3.3-rc (my best guess as to the right one to use).
2. the hello world example performs as expected. Output sent to UART1 appears correctly.
3. attempting to redirect output to other GPIOs doesn't seem to work, but there's nothing in the docs that say it would.
4. my application still doesn't run. Here is the console output I get:

Code: Select all

I (56) boot: ESP-IDF v3.3-rc 2nd stage bootloader
I (56) boot: compile time 13:45:04
I (72) boot: Enabling RNG early entropy source...
I (72) boot: SPI Speed      : 40MHz
I (72) boot: SPI Mode       : DIO
I (75) boot: SPI Flash Size : 4MB
I (79) boot: Partition Table:
I (82) boot: ## Label            Usage          Type ST Offset   Length
I (89) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (97) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (104) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (112) boot:  3 factory          factory app      00 00 00010000 00130000
I (119) boot:  4 ota_0            OTA app          00 10 00140000 00130000
I (127) boot:  5 ota_1            OTA app          00 11 00270000 00130000
I (135) boot: End of partition table
I (139) boot: Defaëh (29) boot: ESP-IDF v3.3-rc 2nd stage bootloader
I (29) boot: compile time 13:48:21
I (41) boot: Enabling RNG early entropy source...
I (42) boot: SPI Speed      : 40MHz
I (42) boot: SPI Mode       : DIO
I (44) boot: SPI Flash Size : 4MB
I (48) boot: Partition Table:
I (51) boot: ## Label            Usage          Type ST Offset   Length
I (59) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (66) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (74) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (81) boot:  3 factory          factory app      00 00 00010000 00130000
I (89) boot:  4 ota_0            OTA app          00 10 00140000 00130000
I (96) boot:  5 ota_1            OTA app          00 11 00270000 00130000
I (104) boot: End of partition table
I (108) boot: Defaulting to factory image
I (112) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x3e588 (255368) map
I (210) esp_image: segment 1: paddr=0x0004e5b0 vaddr=0x3ffb0000 size=0x01a60 (  6752) load
I (213) esp_image: segment 2: paddr=0x00050018 vaddr=0x400d0018 size=0xd7060 (880736) map
I (522) esp_image: segment 3: paddr=0x00127080 vaddr=0x3ffb1a60 size=0x01648 (  5704) load
I (524) esp_image: segment 4: paddr=0x001286d0 vaddr=0x40080000 size=0x00400 (  1024) load
I (529) esp_image: segment 5: paddr=0x00128ad8 vaddr=0x40080400 size=0x1076c ( 67436) load
I (564) esp_image: segment 6: paddr=0x0013924c vaddr=0x400c0000 size=0x00064 (   100) load
I (574) boot: Loaded app from partition at offset 0x10000
I (574) boot: Disabling RNG early entropy source...
I (576) cpu_start: Pro cpu up.
I (579) cpu_start: Application information:
I (584) cpu_start: Project name:     WifiButton
I (589) cpu_start: App version:      V0.1-24-g54a0f12-dirty
I (595) cpu_start: Compile time:     Nov 13 2019 13:48:06
I (602) cpu_start: ELF file SHA256:  5af2e5aa1a4d5eb7...
I (608) cpu_start: ESP-IDF:          v3.3-rc
I (612) cpu_start: Starting app cpu, entry point is 0x40081208
I (0) cpu_start: App cpu up.
I (623) heap_init: Initializing. RAM available for dynamic allocation:
I (630) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (636) heap_init: At 3FFCC4F0 len 00013B10 (78 KiB): DRAM
I (642) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (648) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (655) heap_init: At 40090B6C len 0000F494 (61 KiB): IRAM
I (661) cpu_start: Pro cpu start user code
I (29) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.

This is true whether or not I attempt to divert the console output to UART1.

So...I guess this is no longer an issue with the console. Unless anyone sees a reason not to, I'll mark this resolved and use a different topic to pursue my current issue.

Thanks to all who looked at this.

[WiFive]

rc means release candidate and comes before a stable release. Stable release is v3.3 no suffix.

[mzimmers]

Thanks, WiFive. I suspected that v3.3 was the stable release, but wanted confirmation.

Unfortunately, using v3.3 yields the same (erroneous) behavior for my app as did v3.3-rc.