Closed wuyuanyi135 closed 1 year ago
Supurisingly, it does not starts with the ELF magics (0x7f,E, L, F). See the picture below, the magic bytes in the circle are supposed to be the first bytes.
That part — that the ELF magic is not at the beginning of the coredump partition — is expected and this should be the case every time. In flash, the ELF formatted coredump is prefixed with a header:
Since the coredump-debug command is failing, it's probably a real bug somewhere, though. Thank you for the attached files, we will try to reproduce the issue and debug it.
@wuyuanyi135 for what it's worth, I'm able to debug the unmodified core dump from the attachment using:
espcoredump.py dbg_corefile --core coredump-original -t raw project.elf
I think the problem might be in the part of the script which reads the core dump from flash (this one) — perhaps it doesn't actually read the entire core dump partition. Could you please see if there's anything useful in the output you get from idf.py coredump-debug
before the exception backtrace? For example, any log you see from esptool.py or parttool.py being invoked?
@igrr Thanks for your quick response and explanation!
For the prefixed coredump, I guessed it should be the case since the docs hint so. However, I traced the stacktrace when executing idf.py coredump-debug -c coredump
.
As you may see, it checks the elf magic at the begining of the file. I guess if the coredump was created by idf.py
commands it will strip the extra starting bytes?
Also, I noticed you were using another script espcoredump.py
instead of idf.py coredump-debug
. Could you explain if there is any difference between them?
@igrr For your second request, I attach the full stacktrace here.
Executing action: coredump-debug
Traceback (most recent call last):
File "C:\Espressif\frameworks\esp-idf-master\components\partition_table\parttool.py", line 358, in <module>
main()
File "C:\Espressif\frameworks\esp-idf-master\components\partition_table\parttool.py", line 327, in main
target = ParttoolTarget(**target_args)
File "C:\Espressif\frameworks\esp-idf-master\components\partition_table\parttool.py", line 103, in __init__
self._call_esptool(['read_flash', str(partition_table_offset), str(gen.MAX_PARTITION_LENGTH), temp_file.name])
File "C:\Espressif\frameworks\esp-idf-master\components\partition_table\parttool.py", line 130, in _call_esptool
raise e
File "C:\Espressif\frameworks\esp-idf-master\components\partition_table\parttool.py", line 127, in _call_esptool
subprocess.check_call(esptool_args, stdout=out, stderr=subprocess.STDOUT)
File "subprocess.py", line 364, in check_call
subprocess.CalledProcessError: Command '['C:\\Espressif\\python_env\\idf5.1_py3.8_env\\Scripts\\python.exe', 'C:\\Espressif\\frameworks\\esp-idf-master\\components\\esptool_py\\esptool\\esptool.py', '--port', 'COM6', 'read_flash', '32768', '3072', 'C:\\Users\\wuyua\\AppData\\Local\\Temp\\tmp_9qrjqjo']' returned non-zero exit status 2.
ERROR:root:parttool script execution failed with err 1
ERROR:root:Error during the subprocess execution
Traceback (most recent call last):
File "C:\Espressif\frameworks\esp-idf-master\tools\idf.py", line 767, in <module>
main()
File "C:\Espressif\frameworks\esp-idf-master\tools\idf.py", line 702, in main
cli(sys.argv[1:], prog_name=PROG, complete_var=SHELL_COMPLETE_VAR)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\click\core.py", line 1130, in __call__
return self.main(*args, **kwargs)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\click\core.py", line 1055, in main
rv = self.invoke(ctx)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\click\core.py", line 1689, in invoke
return _process_result(rv)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\click\core.py", line 1626, in _process_result
value = ctx.invoke(self._result_callback, value, **ctx.params)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\click\core.py", line 760, in invoke
return __callback(*args, **kwargs)
File "C:\Espressif\frameworks\esp-idf-master\tools\idf.py", line 605, in execute_tasks
task(ctx, global_args, task.action_args)
File "C:\Espressif\frameworks\esp-idf-master\tools\idf.py", line 187, in __call__
self.callback(self.name, context, global_args, **action_args)
File "C:\Espressif\frameworks\esp-idf-master\tools\idf_py_actions\debug_ext.py", line 537, in coredump_debug
espcoredump.dbg_corefile()
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\esp_coredump\coredump.py", line 329, in dbg_corefile
core_elf_path, target, temp_files = self.get_core_dump_elf(e_machine=exe_elf.e_machine)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\esp_coredump\coredump.py", line 108, in get_core_dump_elf
loader = ESPCoreDumpFlashLoader(self.off, self.chip, port=self.port, baud=self.baud)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\esp_coredump\corefile\loader.py", line 429, in __init__
self.target = self._load_core_src()
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\esp_coredump\corefile\loader.py", line 151, in _load_core_src
_header = EspCoreDumpV1Header.parse(coredump_bytes) # first we use V1 format to get version
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\construct\core.py", line 288, in parse
return self.parse_stream(io.BytesIO(data), **contextkw)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\construct\core.py", line 300, in parse_stream
return self._parsereport(stream, context, "(parsing)")
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\construct\core.py", line 312, in _parsereport
obj = self._parse(stream, context, path)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\construct\core.py", line 2120, in _parse
subobj = sc._parsereport(stream, context, path)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\construct\core.py", line 312, in _parsereport
obj = self._parse(stream, context, path)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\construct\core.py", line 2653, in _parse
return self.subcon._parsereport(stream, context, path)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\construct\core.py", line 312, in _parsereport
obj = self._parse(stream, context, path)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\construct\core.py", line 1041, in _parse
data = stream_read(stream, self.length, path)
File "C:\Espressif\python_env\idf5.1_py3.8_env\lib\site-packages\construct\core.py", line 91, in stream_read
raise StreamError("stream read less than specified amount, expected %d, found %d" % (length, len(data)), path=path)
construct.core.StreamError: Error in path (parsing) -> tot_len
stream read less than specified amount, expected 4, found 0
And I do agree with you that might be some serial connection (the built-in USB-JTAG) problem. I occasionally experience jammed flashing that stopped at certain percent of uploading and CTRL-C could not stop the program - I have to either unplug or reset the board and then it will dump tons of output suddenly.
The PCB and electronics should be fine. I used the USB interface for communication in my app and it worked very stable. Only in bootloader did I experienced the interrupted data transfer. IIRC, this happens since a while ago, and I also felt that the flashing speed gots faster, maybe the bootloader or the flash tool were changed recently?
I also leave my sdkconfig here, in case it provides some insights
Ah, i see. So the actual error is here:
subprocess.CalledProcessError: Command '['C:\\Espressif\\python_env\\idf5.1_py3.8_env\\Scripts\\python.exe', 'C:\\Espressif\\frameworks\\esp-idf-master\\components\\esptool_py\\esptool\\esptool.py', '--port', 'COM6', 'read_flash', '32768', '3072', 'C:\\Users\\wuyua\\AppData\\Local\\Temp\\tmp_9qrjqjo']' returned non-zero exit status 2.
ERROR:root:parttool script execution failed with err 1
ERROR:root:Error during the subprocess execution
Basically, esptool.py has failed to read the coredump partition and exited half-way. Then instead of exiting from the idf.py coredump-debug
script, we carried on and passed the truncated file to coredump loader, which obviously failed because the file was truncated.
So the issue you are facing is probably with esptool.py read_flash not working reliably. I would suggest running this command manually a few times. If you get it to fail occasionally, please check the troubleshooting instructions in https://github.com/espressif/esptool, then in case you can't figure out what the issue is, open a bug report in esptool repository.
The issue that we can fix in this ticket is that idf.py coredump-debug
doesn't bail out on the first error and mistakenly proceeds with parsing the coredump, showing this misleading error message.
Also, I noticed you were using another script espcoredump.py instead of idf.py coredump-debug. Could you explain if there is any difference between them?
idf.py coredump-debug
is correct and is the recommended way to debug the coredump from within an IDF project. espcoredump.py
is a lower-level tool which needs more arguments to be passed manually, because it doesn't "know" about IDF projects, sdkconfig files, and such. I used the latter because I only had your .elf and coredump files, not the whole project, so idf.py coredump-debug
wouldn't work for me. But aside from the differences in command line arguments, these tools use the same code internally (https://github.com/espressif/esp-coredump).
@igrr Many thanks for your detailed explanation.
Yes, I agree that the output should be improved so that the actual problem will not be masked. I will keep monitoring if the bootloader I/O problem persists and open a issue in esptool repository.
@igrr in addition to what you suggest, it also worth noting that the coredump-debug handles the core file differently. When passing the prefixed coredump it assumes it is a base64 encoded file rather than raw elf due to magic check. Maybe this should also be documented or covered.
it assumes it is a base64 encoded file rather than raw elf due to magic check
Thanks for pointing it out. It does have the logic to distinguish the two, but we have forgotten to consider that the chip ID is also stored as part of the version/magic field here. We'll get that fixed, as well.
idf.py coredump-debug
is not available in v5.0, is it?
I'm experiencing a similar issue and I don't know where I should post it. Had I had coredump-info
or coredump-debug
available, I'd have run these commands.
@dizcza it should be available AFAIK. Also, upgrading esptool to 4.6 rather than 4.5 shipped with 5.0 will drastically improve the stability during flashing and coredumping.
Answers checklist.
IDF version.
v5.1-dev-3636-g66ab22986f
Operating System used.
Windows
How did you build your project?
CLion IDE
If you are using Windows, please specify command line type.
PowerShell
Development Kit.
ESP32-S3-WROOM-1-N8R8
Power Supply used.
USB
What is the expected behavior?
-
What is the actual behavior?
I found occasionally,
idf.py coredump-debug
fails with the following stacktrace:Therefore, I dump the coredump partition. Supurisingly, it does not starts with the ELF magics (0x7f,E, L, F). See the picture below, the magic bytes in the circle are supposed to be the first bytes.
I then remove the bytes before the ELF header then debug with
idf.py coredump-debug --core coredump
and it works without problem!Steps to reproduce.
I could not reproduce this error consistently. The coredump partition occasionally broke.
Debug Logs.
No response
More Information.
Partition Table:
Attached archive contains the elf symbol file, modified coredump that can be debugged, and unmodified coredump.
coredump.zip