Consecutive apptrace statements not output to the JTAG console without stepping through (IDFGH-4906) (OCD-319) #149

ToBoMi · 2021-03-12T13:06:24Z

Environment

Development Kit: [none]
Kit version (for WroverKit/PicoKit/DevKitC): []
Module or chip used: [ESP32-WROOM-32]
IDF version (run git describe --tags to find it):
v4.4-dev-4-g73db14240
Build System: [CMake]
Compiler version (run xtensa-esp32-elf-gcc --version to find it):
xtensa-esp32-elf-gcc (crosstool-NG esp-2020r3) 8.4.0
Operating System: [Windows]
(Windows only) environment type: [].
Using an IDE?: [Yes eclipse-plugin]
Power Supply: [USB]

Problem Description

From two consecutive apptrace instruction only the last one gets output to the JTAG console unless one steps through each instruction manually.
I also tried to set the openocd command for tracing to blocking without success.

Expected Behavior

Running the program puts out all trace data each after another without halting the program.

Actual Behavior

Running the program only puts out the trace data of the last apptrace instruction

Steps to reproduce

Setup a Hello World example
Insert the code shown below in the hello_world_main.c
Setup a JTAG flashing debug configuration (see attachement)
Setup a JTAG debug configuration with openocd tracing (see attachement)
Enable application level tracing in sdkconfig
Build
Run by stepping through
Reset
Run without stepping
Compare console output of step 7 and 9

Code to reproduce this issue

/* Hello World Example

   This example code is in the Public Domain (or CC0 licensed, at your option.)

   Unless required by applicable law or agreed to in writing, this
   software is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR
   CONDITIONS OF ANY KIND, either express or implied.
*/
#include <stdio.h>
#include "sdkconfig.h"
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "esp_system.h"
#include "esp_spi_flash.h"
#include "esp_app_trace.h"
#include "esp_log.h"

void app_main(void)
{
    char *ptr = NULL;

    ptr = (char *)esp_apptrace_buffer_get(ESP_APPTRACE_DEST_TRAX, 32, ESP_APPTRACE_TMO_INFINITE/*tmo in us*/);
    if (ptr == NULL) {
        ESP_LOGE("---", "Failed to get buffer!");
    }
    sprintf(ptr, "__Hello World!\n");
    esp_err_t res = esp_apptrace_buffer_put(ESP_APPTRACE_DEST_TRAX, (uint8_t*) ptr, ESP_APPTRACE_TMO_INFINITE/*tmo in us*/);
    res += esp_apptrace_flush(ESP_APPTRACE_DEST_TRAX, ESP_APPTRACE_TMO_INFINITE/*tmo in us*/);
    if (res != ESP_OK) {
        /* in case of error host tracing tool (e.g. OpenOCD) will report incomplete user buffer */
        ESP_LOGE("---", "Failed to put buffer!");
    }

    ptr = (char *)esp_apptrace_buffer_get(ESP_APPTRACE_DEST_TRAX, 32, ESP_APPTRACE_TMO_INFINITE/*tmo in us*/);
    if (ptr == NULL) {
        ESP_LOGE("---", "Failed to get buffer!");
    }
    sprintf(ptr, "__Hello Again!\n");
    res = esp_apptrace_buffer_put(ESP_APPTRACE_DEST_TRAX, (uint8_t*) ptr, ESP_APPTRACE_TMO_INFINITE/*tmo in us*/);
    res += esp_apptrace_flush(ESP_APPTRACE_DEST_TRAX, ESP_APPTRACE_TMO_INFINITE/*tmo in us*/);
    if (res != ESP_OK) {
        /* in case of error host tracing tool (e.g. OpenOCD) will report incomplete user buffer */
        ESP_LOGE("---", "Failed to put buffer!");
    }
}

Debug Logs

Stepping through:

[...]
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
Warn : cpu0: No free slots to add HW breakpoint!
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
__Hello World!
Info : Target halted. CPU0: PC=0x400D4024 (active)
Info : Target halted. CPU1: PC=0x400E2B1E 
Warn : cpu0: HW breakpoint not found!
[...]
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
Warn : cpu0: No free slots to add HW breakpoint!
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
__Hello Again!
Info : Target halted. CPU0: PC=0x400D407C (active)
Info : Target halted. CPU1: PC=0x400E2B1E 
[...]

Running:

Warn : cpu0: No free slots to add HW breakpoint!
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
Info : Target halted. CPU0: PC=0x400D3FE0 (active)
Info : Target halted. CPU1: PC=0x400E2B1E 
Warn : cpu0: HW breakpoint not found!
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
__Hello Again!

Other items if possible

hello_world flash Configuration.launch.txt
hello_world debug Configuration.launch.txt
esp-huzzah-32.cfg.txt (if interesting - nothing special here I think)

The text was updated successfully, but these errors were encountered:

Alvin1Zhang · 2021-03-15T02:48:00Z

Thanks for reporting and sorry for the inconvenience, we will look into.

gerekon · 2021-03-15T10:38:06Z

Hi @TobiasBoeschMiele!

What OpenOCD version do you use? The default one specified by IDF?
I could not find where you invoke esp apptrace ... command to start tracing. Search in debug configuration returned no results.

ToBoMi · 2021-03-15T10:48:16Z

I start it in the hello_world debug Configuration.launch.txt on line 19:
init; esp32 apptrace start con: 0

In eclipse that looks like this:
-s ${openocd_path}/share/openocd/scripts -f ${project_loc}/esp-huzzah-32.cfg -c "init; esp32 apptrace start con: 0"

gerekon · 2021-03-15T11:21:28Z

I start it in the hello_world debug Configuration.launch.txt on line 19:

Ahh, sorry I see. Missed this. I will check the issue.

gerekon · 2021-03-15T21:14:03Z

@TobiasBoeschMiele I can reproduce your problem.
For now as a temporary solution I'd recommend you to start tracing upon hitting breakpoint at app_main. To do this you need to remove esp32 apptrace start con: 0 from OpenOCD command line and use the following GDB inti commands

mon reset halt
flushregs
set remote hardware-watchpoint-limit 2

tb app_main
commands
mon esp32 apptrace start con: 0
c
end

gerekon · 2021-03-16T16:30:28Z

It seems to be OpenOCD issue. So moved it here.

ToBoMi · 2021-03-18T10:47:46Z

It seems to be OpenOCD issue. So moved it here.

Thanks.

tb app_main
commands
mon esp32 apptrace start con: 0
c
end

I've added that to the gdb init commands in eclipse, but I cannot test it since the debug session does not fully start anymore. Do you know why? Logs of the starting and not starting debug session below:

Log not using gdb commands but -c "init; esp32 apptrace start con: 0" when starting openocd which ends in a working debugging session:

Open On-Chip Debugger  v0.10.0-esp32-20200709 (2020-07-09-08:54)
Licensed under GNU GPL v2
For bug reports, read
	http://openocd.org/doc/doxygen/bugs.html
Info: esp-huzzah-32.cfg is not an official configuration file.
Info : Configured 2 cores
Error: libusb_open() failed with LIBUSB_ERROR_NOT_SUPPORTED
Info : ftdi: if you experience problems at higher adapter clocks, try the command "ftdi_tdo_sample_edge falling"
Info : clock speed 20000 kHz
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : Target halted. CPU0: PC=0x400D3FE0 (active)
Info : Target halted. CPU1: PC=0x400E2B1E 
Info : Listening on port 3333 for gdb connections
Info : Total trace memory: 16384 bytes
App trace params: from 2 cores, size 4294967295 bytes, stop_tmo -1 s, poll period 0 ms, wait_rst 0, skip 0 bytes
Connect targets...
Info : Targets connected.
Started by GNU MCU Eclipse
Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Info : accepting 'gdb' connection on tcp/3333
Error: No symbols for FreeRTOS
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f400020, 23 KB
Info : Flash mapping 1: 0x20020 -> 0x400d0020, 76 KB
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
Info : Auto-detected flash bank 'esp32.flash' size 4096 KB
Info : Using flash bank 'esp32.flash' size 4096 KB
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f400020, 23 KB
Info : Flash mapping 1: 0x20020 -> 0x400d0020, 76 KB
Info : Using flash bank 'esp32.irom' size 80 KB
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f400020, 23 KB
Info : Flash mapping 1: 0x20020 -> 0x400d0020, 76 KB
Info : Using flash bank 'esp32.drom' size 24 KB
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : cpu0: Debug controller 0 was reset.
Info : cpu0: Core 0 was reset.
Info : cpu0: Target halted, PC=0x500000CF, debug_reason=00000000
Info : esp32: Core 0 was reset.
Info : esp32: Debug controller 1 was reset.
Info : esp32: Core 1 was reset.
Info : Target halted. CPU0: PC=0x40000400 (active)
Info : Target halted. CPU1: PC=0x40000400 
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : cpu0: Debug controller 0 was reset.
Info : cpu0: Core 0 was reset.
Info : cpu0: Target halted, PC=0x500000CF, debug_reason=00000000
Info : esp32: Core 0 was reset.
Info : esp32: Debug controller 1 was reset.
Info : esp32: Core 1 was reset.
Info : Target halted. CPU0: PC=0x40000400 (active)
Info : Target halted. CPU1: PC=0x40000400 
invalid command name "arm"
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : cpu0: Debug controller 0 was reset.
Info : cpu0: Core 0 was reset.
Info : cpu0: Target halted, PC=0x500000CF, debug_reason=00000000
Info : esp32: Core 0 was reset.
Info : esp32: Debug controller 1 was reset.
Info : esp32: Core 1 was reset.
Info : Target halted. CPU0: PC=0x40000400 (active)
Info : Target halted. CPU1: PC=0x40000400 
===== Xtensa registers
(0) pc (/32): 0x40000400
(1) ar0 (/32): 0x00000000
(2) ar1 (/32): 0x00000000
(3) ar2 (/32): 0x00000000
(4) ar3 (/32): 0x00000000
(5) ar4 (/32): 0x00000000
(6) ar5 (/32): 0x00000000
(7) ar6 (/32): 0x00000000
(8) ar7 (/32): 0x00000000
(9) ar8 (/32): 0x00000000
(10) ar9 (/32): 0x00000000
(11) ar10 (/32): 0x00000000
(12) ar11 (/32): 0x00000000
(13) ar12 (/32): 0x00000000
(14) ar13 (/32): 0x00000000
(15) ar14 (/32): 0x00000000
(16) ar15 (/32): 0x00000000
(17) ar16 (/32): 0x00000000
(18) ar17 (/32): 0x00000000
(19) ar18 (/32): 0x00000000
(20) ar19 (/32): 0x00000000
(21) ar20 (/32): 0x00000000
(22) ar21 (/32): 0x00000000
(23) ar22 (/32): 0x00000000
(24) ar23 (/32): 0x00000000
(25) ar24 (/32): 0x00000000
(26) ar25 (/32): 0x00000000
(27) ar26 (/32): 0x00000000
(28) ar27 (/32): 0x00000000
(29) ar28 (/32): 0x00000000
(30) ar29 (/32): 0x00000000
(31) ar30 (/32): 0x00000000
(32) ar31 (/32): 0x00000000
(33) ar32 (/32): 0x00000000
(34) ar33 (/32): 0x00000000
(35) ar34 (/32): 0x00000000
(36) ar35 (/32): 0x00000000
(37) ar36 (/32): 0x00000000
(38) ar37 (/32): 0x00000000
(39) ar38 (/32): 0x00000000
(40) ar39 (/32): 0x00000000
(41) ar40 (/32): 0x00000000
(42) ar41 (/32): 0x00000000
(43) ar42 (/32): 0x00000000
(44) ar43 (/32): 0x00000000
(45) ar44 (/32): 0x00000000
(46) ar45 (/32): 0x00000000
(47) ar46 (/32): 0x00000000
(48) ar47 (/32): 0x00000000
(49) ar48 (/32): 0x00000000
(50) ar49 (/32): 0x00000000
(51) ar50 (/32): 0x00000000
(52) ar51 (/32): 0x00000000
(53) ar52 (/32): 0x00000000
(54) ar53 (/32): 0x00000000
(55) ar54 (/32): 0x00000000
(56) ar55 (/32): 0x00000000
(57) ar56 (/32): 0x00000000
(58) ar57 (/32): 0x00000000
(59) ar58 (/32): 0x00000000
(60) ar59 (/32): 0x00000000
(61) ar60 (/32): 0x00000000
(62) ar61 (/32): 0x00000000
(63) ar62 (/32): 0x00000000
(64) ar63 (/32): 0x00000000
(65) lbeg (/32): 0x00000000
(66) lend (/32): 0x00000000
(67) lcount (/32): 0x00000000
(68) sar (/32): 0x00000000
(69) windowbase (/32): 0x00000000
(70) windowstart (/32): 0x00000001
(71) configid0 (/32): 0x40000400
(72) configid1 (/32): 0x1CC5FE96
(73) ps (/32): 0x0000001F
(74) threadptr (/32): 0x00000000
(75) br (/32): 0x00000000
(76) scompare1 (/32): 0x00000000
(77) acclo (/32): 0x00000000
(78) acchi (/32): 0x00000000
(79) m0 (/32): 0x00000000
(80) m1 (/32): 0x00000000
(81) m2 (/32): 0x00000000
(82) m3 (/32): 0x00000000
(83) expstate (/32): 0x00000000
(84) f64r_lo (/32): 0x00000000
(85) f64r_hi (/32): 0x00000000
(86) f64s (/32): 0x00000000
(87) f0 (/32): 0x00000000
(88) f1 (/32): 0x00000000
(89) f2 (/32): 0x00000000
(90) f3 (/32): 0x00000000
(91) f4 (/32): 0x00000000
(92) f5 (/32): 0x00000000
(93) f6 (/32): 0x00000000
(94) f7 (/32): 0x00000000
(95) f8 (/32): 0x00000000
(96) f9 (/32): 0x00000000
(97) f10 (/32): 0x00000000
(98) f11 (/32): 0x00000000
(99) f12 (/32): 0x00000000
(100) f13 (/32): 0x00000000
(101) f14 (/32): 0x00000000
(102) f15 (/32): 0x00000000
(105) mmid (/32)
(106) ibreakenable (/32): 0x00000000
(107) memctl (/32): 0x00000000
(108) atomctl (/32): 0x00000028
(109) ddr (/32)
(110) ibreaka0 (/32): 0x00000000
(111) ibreaka1 (/32): 0x00000000
(112) dbreaka0 (/32): 0x00000000
(113) dbreaka1 (/32): 0x00000000
(114) dbreakc0 (/32): 0x00000000
(115) dbreakc1 (/32): 0x00000000
(116) epc1 (/32): 0x00000000
(117) epc2 (/32): 0x00000000
(118) epc3 (/32): 0x00000000
(119) epc4 (/32): 0x00000000
(120) epc5 (/32): 0x00000000
(121) epc6 (/32): 0x40000400
(122) epc7 (/32): 0x00000000
(123) depc (/32): 0x00000000
(124) eps2 (/32): 0x00000000
(125) eps3 (/32): 0x00000000
(126) eps4 (/32): 0x00000000
(127) eps5 (/32): 0x00000000
(128) eps6 (/32): 0x0000001F
(129) eps7 (/32): 0x00000000
(130) excsave1 (/32): 0x00000000
(131) excsave2 (/32): 0x00000000
(132) excsave3 (/32): 0x00000000
(133) excsave4 (/32): 0x00000000
(134) excsave5 (/32): 0x00000000
(135) excsave6 (/32): 0x00000000
(136) excsave7 (/32): 0x00000000
(137) cpenable (/32): 0x000000FF
(138) interrupt (/32): 0x00018040
(139) intset (/32)
(140) intclear (/32)
(141) intenable (/32): 0x00000000
(143) exccause (/32): 0x00000000
(144) debugcause (/32): 0x00000020
(145) ccount (/32): 0x00000004
(147) icount (/32): 0x00000000
(148) icountlevel (/32): 0x00000000
(149) excvaddr (/32): 0x00000000
(150) ccompare0 (/32): 0x00000000
(151) ccompare1 (/32): 0x00000000
(152) ccompare2 (/32): 0x00000000
(153) misc0 (/32): 0x00000000
(154) misc1 (/32): 0x00000000
(155) misc2 (/32): 0x00000000
(156) misc3 (/32): 0x00000000
(168) a0 (/32): 0x00000000
(169) a1 (/32): 0x00000000
(170) a2 (/32): 0x00000000
(171) a3 (/32): 0x00000000 (dirty)
(172) a4 (/32): 0x00000000
(173) a5 (/32): 0x00000000
(174) a6 (/32): 0x00000000
(175) a7 (/32): 0x00000000
(176) a8 (/32): 0x00000000
(177) a9 (/32): 0x00000000
(178) a10 (/32): 0x00000000
(179) a11 (/32): 0x00000000
(180) a12 (/32): 0x00000000
(181) a13 (/32): 0x00000000
(182) a14 (/32): 0x00000000
(183) a15 (/32): 0x00000000

Warn : cpu0: No free slots to add HW breakpoint!
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
Info : Target halted. CPU0: PC=0x400D3FE0 (active)
Info : Target halted. CPU1: PC=0x400E2B1E 
Warn : cpu0: HW breakpoint not found!
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001

Log using gdb commands which ends in a NOT working debugging session:

Open On-Chip Debugger  v0.10.0-esp32-20200709 (2020-07-09-08:54)
Licensed under GNU GPL v2
For bug reports, read
	http://openocd.org/doc/doxygen/bugs.html
Info: esp-huzzah-32.cfg is not an official configuration file.
Info : Configured 2 cores
Started by GNU MCU Eclipse
Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Error: libusb_open() failed with LIBUSB_ERROR_NOT_SUPPORTED
Info : ftdi: if you experience problems at higher adapter clocks, try the command "ftdi_tdo_sample_edge falling"
Info : clock speed 20000 kHz
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : Target halted. CPU0: PC=0x40000400 (active)
Info : Target halted. CPU1: PC=0x40000400 
Info : Listening on port 3333 for gdb connections
Info : accepting 'gdb' connection on tcp/3333
Error: No symbols for FreeRTOS
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f400020, 23 KB
Info : Flash mapping 1: 0x20020 -> 0x400d0020, 76 KB
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
Info : Auto-detected flash bank 'esp32.flash' size 4096 KB
Info : Using flash bank 'esp32.flash' size 4096 KB
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f400020, 23 KB
Info : Flash mapping 1: 0x20020 -> 0x400d0020, 76 KB
Info : Using flash bank 'esp32.irom' size 80 KB
Info : cpu0: Target halted, PC=0x40091856, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f400020, 23 KB
Info : Flash mapping 1: 0x20020 -> 0x400d0020, 76 KB
Info : Using flash bank 'esp32.drom' size 24 KB
undefined debug reason 8 - target needs reset
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : cpu0: Debug controller 0 was reset.
Info : cpu0: Core 0 was reset.
Info : cpu0: Target halted, PC=0x500000CF, debug_reason=00000000
Info : esp32: Core 0 was reset.
Info : esp32: Debug controller 1 was reset.
Info : esp32: Core 1 was reset.
Info : Target halted. CPU0: PC=0x40000400 (active)
Info : Target halted. CPU1: PC=0x40000400 
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : cpu0: Debug controller 0 was reset.
Info : cpu0: Core 0 was reset.
Info : cpu0: Target halted, PC=0x500000CF, debug_reason=00000000
Info : esp32: Core 0 was reset.
Info : esp32: Debug controller 1 was reset.
Info : esp32: Core 1 was reset.
Info : Target halted. CPU0: PC=0x40000400 (active)
Info : Target halted. CPU1: PC=0x40000400

The entry undefined debug reason 8 - target needs reset seems new in the NOT working log.

SimonPVS · 2021-04-26T13:49:18Z

Any updates on this?

gerekon · 2021-04-26T19:07:10Z

@SimonPVS @TobiasBoeschMiele Sorry, not yet. I asked a guy to have a look at it.

erhankur · 2021-05-20T18:31:06Z

@SimonPVS @TobiasBoeschMiele you can try with the latest commit. Please make sure to wait host connection before sending data.

    while (!esp_apptrace_host_is_connected(ESP_APPTRACE_DEST_TRAX))       
          vTaskDelay(1);

ToBoMi · 2021-05-25T14:02:58Z

Please make sure to wait host connection before sending data.

Waiting for something here is not what I would like to do. Can I also ask if a connection is established and then "print" the data?

I'll try that and report back.

erhankur · 2021-05-25T20:12:31Z

Yes. Once you connect before sending the first data, it should stay connected until the stop condition is met.

If you don't want to block your applicationesp_apptrace_host_is_connected(ESP_APPTRACE_DEST_TRAX) will return the connection status. true: connected false: not connected

ToBoMi · 2021-06-14T12:58:28Z

I was able to test this with commit 1d7068e4be430edd92bb63f2d922036dcf5c3cc1.
I added

while (!esp_apptrace_host_is_connected(ESP_APPTRACE_DEST_TRAX))       
          vTaskDelay(1);

in the hello-world example code mentioned above in this issue as the first statement:

void app_main(void)
{
    char *ptr = NULL;

    // Added:
    while (!esp_apptrace_host_is_connected(ESP_APPTRACE_DEST_TRAX))       
          vTaskDelay(1);  

    ptr = (char *)esp_apptrace_buffer_get(ESP_APPTRACE_DEST_TRAX, 32, ESP_APPTRACE_TMO_INFINITE/*tmo in us*/);
    if (ptr == NULL) {
        ESP_LOGE("---", "Failed to get buffer!");
    }
[...]

That makes the task wait forever.

Without the waiting statement the example code does what it did before updating to 1d7068e4be430edd92bb63f2d922036dcf5c3cc1: It only

puts out the trace data of the last apptrace instruction

erhankur · 2021-06-14T18:50:31Z

Hi @TobiasBoeschMiele ,

Did you update your openocd?

I have re-tested with the latest openocd commit and with the idf you mentioned. It is working as expected.

:apptrace-test $ ocd32ethkit -c "init; esp32 apptrace start con: 0"
Open On-Chip Debugger  v0.10.0-esp32-20210401-39-gfd267384 (2021-06-14-21:36)
Licensed under GNU GPL v2
For bug reports, read
	http://openocd.org/doc/doxygen/bugs.html
Info : ftdi: if you experience problems at higher adapter clocks, try the command "ftdi_tdo_sample_edge falling"
Info : clock speed 20000 kHz
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : esp32.cpu0: Debug controller was reset.
Info : esp32.cpu0: Core was reset.
Info : esp32.cpu1: Debug controller was reset.
Info : esp32.cpu1: Core was reset.
Info : Listening on port 3333 for gdb connections
Info : Total trace memory: 16384 bytes
App trace params: from 2 cores, size 4294967295 bytes, stop_tmo -1 s, poll period 0 ms, wait_rst 0, skip 0 bytes
Connect targets...
Info : esp32.cpu0: Target halted, PC=0x400E3A8E, debug_reason=00000000
Info : Set GDB target to 'esp32.cpu0'
Info : esp32.cpu1: Target halted, PC=0x400E3A8E, debug_reason=00000000
Info : Targets connected.
Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
__Hello World!
__Hello Again!
Info : esp32.cpu0: Debug controller was reset.
Info : esp32.cpu0: Core was reset.
Warn : esp32.cpu0 apptrace connection is lost. Re-connect.
Warn : esp32.cpu1 apptrace connection is lost. Re-connect.
Warn : esp32.cpu1 apptrace connection is lost. Re-connect.
Info : esp32.cpu1: Debug controller was reset.
Info : esp32.cpu1: Core was reset.
Warn : esp32.cpu1 apptrace connection is lost. Re-connect.
Warn : esp32.cpu0 apptrace connection is lost. Re-connect.
Warn : esp32.cpu1 apptrace connection is lost. Re-connect.
__Hello World!
__Hello Again!

I (185) cpu_start: App cpu up.
I (213) cpu_start: Pro cpu start user code
I (214) cpu_start: cpu freq: 160000000
I (214) cpu_start: Application information:
I (218) cpu_start: Project name:     apptrace
I (223) cpu_start: App version:      1
I (227) cpu_start: Compile time:     Jun 14 2021 21:15:41
I (234) cpu_start: ELF file SHA256:  9efd50f28d94e67b...
I (240) cpu_start: ESP-IDF:          v4.4-dev-1594-g1d7068e4be
I (246) heap_init: Initializing. RAM available for dynamic allocation:
I (253) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (259) heap_init: At 3FFB30B0 len 0002CF50 (179 KiB): DRAM
I (266) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (272) heap_init: At 3FFE4350 len 00013CB0 (79 KiB): D/IRAM
I (278) heap_init: At 4008B19C len 00014E64 (83 KiB): IRAM
I (285) esp_apptrace: Initialized TRAX on CPU0
I (290) spi_flash: detected chip: generic
I (294) spi_flash: flash io: dio
W (298) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (313) cpu_start: Starting scheduler on PRO CPU.
I (203) esp_apptrace: Initialized TRAX on CPU1
I (0) cpu_start: Starting scheduler on APP CPU.
E (1997) ---: Heartbeat!
E (2747) ---: Heartbeat!
E (3497) ---: Heartbeat!
E (4247) ---: Heartbeat!

ToBoMi · 2021-06-15T07:28:20Z

Did you update your openocd?

Not intentionally. I updated esp-idf to the mentioned commit (reset hard with all submodules) and then started the tools install again. (I use the eclipse plugin and used the GUI to start the tools install)
That should also update openocd I think.
I'll test it again and check my version of openocd. With which openocd version did you test it?

I also use a different command for debugging, too I think. In the eclipse GUI I have a debug configuration with this command:

[openocdExecutable] -s ${openocd_path}/share/openocd/scripts -f ${project_loc}/esp-huzzah-32.cfg -c "init; esp32 apptrace start con:"

The huzzah configuration just lists the JTAG interface and adapter speed.

gerekon · 2021-06-15T09:46:54Z

@TobiasBoeschMiele

Not intentionally. I updated esp-idf to the mentioned commit (reset hard with all submodules) and then started the tools install again. (I use the eclipse plugin and used the GUI to start the tools install)

That fix in OpenOCD is not released yet. So you need to build OpenOCD from master. Will be released in the nearest future. We are testing new release.

@erhankur Am I right?

gerekon · 2021-06-15T09:48:09Z

@TobiasBoeschMiele

If you are not able to build OpenOCD yourself we can upload binaries for your OS for pre-release check

erhankur · 2021-06-15T10:17:10Z

@gerekon you are right. Build from master branch is needed to validate.

@TobiasBoeschMiele Regarding openocd configuration before -c part can be different according to your board. For apptrace commands you can read details from https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-guides/app_trace.html#openocd-application-level-tracing-commands

ToBoMi · 2021-06-15T11:24:25Z

@TobiasBoeschMiele

If you are not able to build OpenOCD yourself we can upload binaries for your OS for pre-release check

That would be helpful. I don't know if I need special tools for building, but I don't have administrative rights on my machine. So it might take a while.

Operating System: [Windows]

ToBoMi · 2021-06-15T11:30:53Z

@gerekon you are right. Build from master branch is needed to validate.

@TobiasBoeschMiele Regarding openocd configuration before -c part can be different according to your board. For apptrace commands you can read details from https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-guides/app_trace.html#openocd-application-level-tracing-commands

We come back to check that if there is the issue persists after using the correct openocd version. Thanks.

erhankur · 2021-06-15T11:43:09Z

You can try with this windows build.

openocd-esp32-win32-0.10.0-esp32-20210401-39-gfd267384f.zip

ToBoMi · 2021-06-15T12:40:32Z

You can try with this windows build.

openocd-esp32-win32-0.10.0-esp32-20210401-39-gfd267384f.zip

Using this build makes the issue dissapear.
I don't need to add the following statement to wait for the connection to be established, but that might be just a lucky case where the connection is already present.

    while (!esp_apptrace_host_is_connected(ESP_APPTRACE_DEST_TRAX))       
          vTaskDelay(1);

erhankur · 2021-06-15T12:56:28Z

Yes, it will not be stable without waiting the connection. That was the lucky case.

ToBoMi · 2021-06-16T06:45:26Z

Thanks for your help.

github-actions bot changed the title ~~Consecutive apptrace statements not output to the JTAG console without stepping through~~ Consecutive apptrace statements not output to the JTAG console without stepping through (IDFGH-4906) Mar 12, 2021

gerekon transferred this issue from espressif/esp-idf Mar 16, 2021

github-actions bot changed the title ~~Consecutive apptrace statements not output to the JTAG console without stepping through (IDFGH-4906)~~ Consecutive apptrace statements not output to the JTAG console without stepping through (IDFGH-4906) (OCD-319) Mar 16, 2021

ToBoMi closed this as completed Jun 15, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Consecutive apptrace statements not output to the JTAG console without stepping through (IDFGH-4906) (OCD-319) #149

Consecutive apptrace statements not output to the JTAG console without stepping through (IDFGH-4906) (OCD-319) #149

ToBoMi commented Mar 12, 2021

Alvin1Zhang commented Mar 15, 2021

gerekon commented Mar 15, 2021 •

edited

Loading

ToBoMi commented Mar 15, 2021 •

edited

Loading

gerekon commented Mar 15, 2021

gerekon commented Mar 15, 2021 •

edited

Loading

gerekon commented Mar 16, 2021

ToBoMi commented Mar 18, 2021

SimonPVS commented Apr 26, 2021

gerekon commented Apr 26, 2021

erhankur commented May 20, 2021

ToBoMi commented May 25, 2021 •

edited

Loading

erhankur commented May 25, 2021 •

edited

Loading

ToBoMi commented Jun 14, 2021 •

edited

Loading

erhankur commented Jun 14, 2021 •

edited

Loading

ToBoMi commented Jun 15, 2021

gerekon commented Jun 15, 2021

gerekon commented Jun 15, 2021 •

edited

Loading

erhankur commented Jun 15, 2021

ToBoMi commented Jun 15, 2021 •

edited

Loading

ToBoMi commented Jun 15, 2021

erhankur commented Jun 15, 2021

ToBoMi commented Jun 15, 2021 •

edited

Loading

erhankur commented Jun 15, 2021

ToBoMi commented Jun 16, 2021

Consecutive apptrace statements not output to the JTAG console without stepping through (IDFGH-4906) (OCD-319) #149

Consecutive apptrace statements not output to the JTAG console without stepping through (IDFGH-4906) (OCD-319) #149

Comments

ToBoMi commented Mar 12, 2021

Environment

Problem Description

Expected Behavior

Actual Behavior

Steps to reproduce

Code to reproduce this issue

Debug Logs

Other items if possible

Alvin1Zhang commented Mar 15, 2021

gerekon commented Mar 15, 2021 • edited Loading

ToBoMi commented Mar 15, 2021 • edited Loading

gerekon commented Mar 15, 2021

gerekon commented Mar 15, 2021 • edited Loading

gerekon commented Mar 16, 2021

ToBoMi commented Mar 18, 2021

SimonPVS commented Apr 26, 2021

gerekon commented Apr 26, 2021

erhankur commented May 20, 2021

ToBoMi commented May 25, 2021 • edited Loading

erhankur commented May 25, 2021 • edited Loading

ToBoMi commented Jun 14, 2021 • edited Loading

erhankur commented Jun 14, 2021 • edited Loading

ToBoMi commented Jun 15, 2021

gerekon commented Jun 15, 2021

gerekon commented Jun 15, 2021 • edited Loading

erhankur commented Jun 15, 2021

ToBoMi commented Jun 15, 2021 • edited Loading

ToBoMi commented Jun 15, 2021

erhankur commented Jun 15, 2021

ToBoMi commented Jun 15, 2021 • edited Loading

erhankur commented Jun 15, 2021

ToBoMi commented Jun 16, 2021

gerekon commented Mar 15, 2021 •

edited

Loading

ToBoMi commented Mar 15, 2021 •

edited

Loading

gerekon commented Mar 15, 2021 •

edited

Loading

ToBoMi commented May 25, 2021 •

edited

Loading

erhankur commented May 25, 2021 •

edited

Loading

ToBoMi commented Jun 14, 2021 •

edited

Loading

erhankur commented Jun 14, 2021 •

edited

Loading

gerekon commented Jun 15, 2021 •

edited

Loading

ToBoMi commented Jun 15, 2021 •

edited

Loading

ToBoMi commented Jun 15, 2021 •

edited

Loading