esp_log_set_vprintf() issue, ESP32 S2 panics while calling vfprintf (logfile, format, args) inside the new function.

[RalphD]

IDF 5.0

Hello folks,

I am working now on an issue I do not find even an explanation for.

The following function writes seamlessly some logs to the SD card before core 0 panics with "Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled."

Code: Select all

static int mday;
static int inUse = 0;

vprintf_like_t my_IRAM_ATTR  vprintf( const char *format, ... ){

	va_list args;
	FILE * logfile = NULL;
	time_t now;

	while( inUse){
    	vTaskDelay(100 / portTICK_PERIOD_MS);
	}
	inUse++;

    struct tm timeinfo;
    time(&now);
    localtime_r(&now, &timeinfo);
    if(timeinfo.tm_mday != mday){
    	mday = timeinfo.tm_mday;
    }

	char filename[strlen(MOUNT_POINT)+40];
	memset(filename,0,sizeof(filename));
	strcat(filename,MOUNT_POINT);

	sprintf( &filename[strlen(MOUNT_POINT)], "/[%04i-%02i-%02i].log", (timeinfo.tm_year+1900), (timeinfo.tm_mon+1), timeinfo.tm_mday);

	// open file if not open
	if(!logfile)
		logfile = fopen(filename, "a");
	if (!logfile){
		inUse--;
		return NULL;
	}
	va_start (args, format);
		vfprintf (logfile, format, args);
	va_end (args);
	fclose(logfile);
	logfile = NULL;
	inUse--;
	return NULL;
}

This works fine if I do not try to use the args pointer. In trying finding the root cause I also tried to go through the variable argument list bit by bit with the same result and not being able to identify the variable which is not in access from this function.

I looked on the web and people seem to use esp_log_set_vprintf() with no problem, and I can use it without problem as long as i do not try to access any of the variables in the variable list.

e.g. this useless function works fine just printing the format string to SD card

Code: Select all

vprintf_like_t IRAM_ATTR maxill_vprintf( const char *format, ... ){

	va_list args;
	FILE * logfile = NULL;
	time_t now;

	char * frmt = strdup(format);

	while( inUse){
    	vTaskDelay(100 / portTICK_PERIOD_MS);
	}
	inUse++;

	// ****** create and open file name
    struct tm timeinfo;
    time(&now);
    localtime_r(&now, &timeinfo);
    if(timeinfo.tm_mday != mday){
    	mday = timeinfo.tm_mday;
    }

	char filename[strlen(MOUNT_POINT)+40];
	memset(filename,0,sizeof(filename));
	strcat(filename,MOUNT_POINT);

	sprintf( &filename[strlen(MOUNT_POINT)], "/[%04i-%02i-%02i].log", (timeinfo.tm_year+1900), (timeinfo.tm_mon+1), timeinfo.tm_mday);

	// open file if not open
	if(!logfile)
		logfile = fopen(filename, "a");
	if (!logfile){
		inUse--;
		return NULL;
	}

	// how many format tokens are in format
	int ccount = char_in_str( format, '%');
	char *token;

	va_start (args, format);

	// vfprintf (logfile, format, args);

	size_t bufsize = snprintf((char *)0, 0, "%s", format);

	char * buffer = malloc(bufsize+1);
	bufsize = snprintf( buffer, bufsize, "%s", format);

	va_end (args);
	fwrite( buffer, sizeof(char), bufsize, logfile);
	fclose(logfile);
	free(buffer);
	logfile = NULL;
	inUse--;
	free(frmt);
	return NULL;
}

Any hint welcome!

Best wishes

Ralph

[ESP_Sprite]

Did you get a backtrace? Can you decode that, and if so, where does it point at? Also note that your makeshift 'inUse' atomic/mutex is not threadsafe as you 'can sneak in' a write between the read and the write of 'inUse++'. Suggest to use a proper FreeRTOS mutex there.

[RalphD]

Noop, I am not getting a backtrace all I get is this:

Code: Select all

Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Setting breakpoint at 0x4001af44 and returning...

However I am pretty sure that the vprintf function tries to access a variable either out of reach from this context or not word aligned like required if running from IRAM. However I tried before to run this function from normal memory with the same result.

I am working on what type of data are causing this problem. If the format string indicates only standard data type conversion like %s or %d everything works fine. Currently the %llu seems to be suspicious to me. there is a log coming in with this data type to print.

[RalphD]

I just wanna bring this up again. please any idea how to nail this down will be needed. I am not getting any back-trace at all.

[ESP_Sprite]

Setting breakpoint at 0x4001af44 and returning...

This usually indicates you've got JTAG attached; is that true? Can you either use that to get a backtrace, or disconnect JTAG so you can get a proper backtrace over serial?

[RalphD]

Further investigation guided to that it seems that the va-args macros do not work inside the function set by esp_log_set_vprintf().

I tried the following code, while the same code works in the first function it does not in the esp_log_set_vprintf() context.

Code: Select all

/*
 * SPDX-FileCopyrightText: 2010-2022 Espressif Systems (Shanghai) CO LTD
 *
 * SPDX-License-Identifier: CC0-1.0
 */

#include <stdio.h>
#include <stdarg.h>
#include <esp_log.h>
#include "sdkconfig.h"
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"

void testit (char *fmt, ...)
{
    va_list argptr;
    va_start(argptr, fmt);

    vprintf(fmt, argptr);
    va_end(argptr);
}

vprintf_like_t vtestit(char *fmt, ...){
    va_list argptr;
    va_start(argptr, fmt);

    vprintf(fmt, argptr);
    va_end(argptr);
    return 0;
}

void app_main(void)
{
	esp_log_set_vprintf(&vtestit);

    while(1){

    	testit( "%s - %d", "testing ....", 10);

    	ESP_LOGI("test", "-->%s", "teeest");

		printf("Hello world!\n");
		fflush(stdout);
		vTaskDelay(1000 / portTICK_PERIOD_MS);
    }
}

The break point hit is always at address 0x40007e40, always.




here in another code context



I do not get any back trace or don't know how I can get it in this case.

[ESP_Sprite]

Looking through others code, could your problem be that you structure your callback function as a printf-like, and not a vprintf-like?

Code: Select all

vprintf_like_t vtestit(char *fmt, ...) {

vs

Code: Select all

int vprintf (const char *template, va_list ap) {