va_list thread-safe внутри critical region?, HardFault под FreeRTOS из-за va_arg Опции

[Cosmojam]

Всем привет!
Подскажите где я не прав.
Имеется примерно такой код для LPC1768 с FreeRTOS:

Код

uint_fast8_t syslog_write(SysLogRecordType type, const signed char * const threadname, const char *fmt, ...)
{
    /* whatever */
      char string[SYSLOG_MAXLINE] = {0};

    taskENTER_CRITICAL();

    va_list args;
    va_start(args, fmt);
    length = format_string(string, sizeof string, type, threadname, fmt, args);
    va_end(args);

    taskEXIT_CRITICAL();

        /* whatever */
}

Вызывается это из разных задач.

Функция format_string():

Код

static size_t format_string(char *buffer, size_t size, SysLogRecordType type, const char * const threadname, const char *fmt, va_list args)
{
/* whatever */
       vsprintf(buffer, fmt, args);

  /* whatever */
}

Проблема в том что когда syslog_write() вызывается в разных потоках, то в vsprintf() происходит HardFault (CFSR = 0x8200). Если заменить эту функцию на что угодно типа sprintf(buffer, "hi there") то всё работает стабильно. Т.е. связано это как-то с va_list. Я честно говоря плохо понимаю как эта фишка работае. При этом вызов её обёрнут в taskENTER_CRITICAL();
Если же syslog_write() вызывается только в одном потоке, то никаких проблем. Но стоит ему вызываться в разных вытесняющих друг друга - периодические фолты.

[aaarrr]

ИМХО:

1. Посмотреть дизассемблер

2. Завернуть через макрос

Код

#define syslog_write_safe(...)  \
{                               \
    taskENTER_CRITICAL();       \
    syslog_write(__VA_ARGS__);  \
    taskEXIT_CRITICAL();        \
}

[Cosmojam]

Обёртка в макрос не помогла. Тоже самое. Не помог и рекурсивный мьютекс.
Происходит Bus Fault, при этом в регистре BFAR записывается валидный адрес места где произошёл этот эксепшен.
В этом регистре 0x201A8C0 что за пределами адресного пространства.
В отладчике ловится последняя инструкция перед после которой произошёл эксепшен и это:

main:
0000d860: main+0 push {r4, r5, r6, r7, lr}
0000d862: main+2 sub sp, #44 ; 0x2c
87 PinCfg.Funcnum = PINSEL_FUNC_1;
0000d864: main+4 mov.w r6, #1 <<<<<<<<<<<<<<<<<<< вот тут

Это main() и настройка портов для юарта. В регистре R6 после того как произошёл эксепшен лежит 0x201A8C0
Но как она оказалась в main() если уже все задачи запустились? Где-то косяк с указателями видимо
Дизассемблер vsnprintf (в примере кода обычный указан vsprintf, но без разницы что обычный что с "n" и размером буфера)

Код

0000ee08 <vsnprintf>:
    ee08:    b5f0          push    {r4, r5, r6, r7, lr}
    ee0a:    b08f          sub    sp, #60; 0x3c
    ee0c:    4606          mov    r6, r0
    ee0e:    460c          mov    r4, r1
    ee10:    4615          mov    r5, r2
    ee12:    2100          movs    r1, #0
    ee14:    2228          movs    r2, #40; 0x28
    ee16:    a804          add    r0, sp, #16
    ee18:    461f          mov    r7, r3
    ee1a:    f001 f94d     bl    100b8 <memset>
    ee1e:    230a          movs    r3, #10
    ee20:    9307          str    r3, [sp, #28]
    ee22:    f06f 4300     mvn.w    r3, #2147483648; 0x80000000
    ee26:    9306          str    r3, [sp, #24]
    ee28:    4b0d          ldr    r3, [pc, #52]; (ee60 <vsnprintf+0x58>)
    ee2a:    9604          str    r6, [sp, #16]
    ee2c:    2600          movs    r6, #0
    ee2e:    1e62          subs    r2, r4, #1
    ee30:    9302          str    r3, [sp, #8]
    ee32:    a804          add    r0, sp, #16
    ee34:    4633          mov    r3, r6
    ee36:    9500          str    r5, [sp, #0]
    ee38:    9701          str    r7, [sp, #4]
    ee3a:    f000 f9e9     bl    f210 <__vfprintf>
    ee3e:    9b06          ldr    r3, [sp, #24]
    ee40:    4604          mov    r4, r0
    ee42:    3b01          subs    r3, #1
    ee44:    42b3          cmp    r3, r6
    ee46:    9306          str    r3, [sp, #24]
    ee48:    db02          blt.n    ee50 <vsnprintf+0x48>
    ee4a:    9b04          ldr    r3, [sp, #16]
    ee4c:    701e          strb    r6, [r3, #0]
    ee4e:    e003          b.n    ee58 <vsnprintf+0x50>
    ee50:    4630          mov    r0, r6
    ee52:    a904          add    r1, sp, #16
    ee54:    f001 f954     bl    10100 <__flsbuf>
    ee58:    4620          mov    r0, r4
    ee5a:    b00f          add    sp, #60; 0x3c
    ee5c:    bdf0          pop    {r4, r5, r6, r7, pc}
    ee5e:    bf00          nop
    ee60:    0000e4f1     .word    0x0000e4f1

На ночь глядя это мало о чём говорит

[Terminator]

Надо выкинуть обёртку и защитить только вывод буфера. Куда вы его вываливете?

[Cosmojam]

Надо выкинуть обёртку и защитить только вывод буфера. Куда вы его вываливете?

Буфер записывается в очередь с максимальным таймаутом 2 секунды. Эту очередь читает другая задача с 0 приоритетом, которая собственно пишет данные на устройства хранения (для теста - printf на UART обёрнутый в critical region). Даже если выкинуть запись в очередь и не создавать задачу, которая её читает, то результат тот же самый - само наличие вызова vprintf c va_list в качестве параметра создаёт ошибки.

[Terminator]

А стека-то под:

char string[SYSLOG_MAXLINE]

Везде хватает?

[_Артём_]

А стека-то под:
Везде хватает?

А может всё-таки размер heap слишком мал?

[Cosmojam]

Стека хватает - к гадалке не ходи. Пробовал безумные размеры выделять где "640кб всем хватит"
А насчёт кучи на NXP-шном форуме подсказали http://support.code-red-tech.com/CodeRedWiki/redlib_v2_notes макрос CR_PRINTF_CHAR чтобы printf() не выделяла память в куче под всю строку, а печатала по-символьно. Не помогло. Да и ведь там про printf()говорится, которые выделяет память прежде чем напечатать строку в символьное устройство, а у меня vsnprintf() который печатает строку в буфер и не более переданного размера буфера. Т.е. куча ему пофигу покуда буфер на стеке задачи. Но если разместить буфер в bss (сделав его static) то никаких изменений в поведении не наблюдается.
Если уж на то пошло посоветуйте достойный аналог vsnprint(). Вещественные числа не нужны, только целые со знаком и без и строки, и чтобы не пыталась выделять память без спроса

Сообщение отредактировал Cosmojam - Oct 16 2012, 18:18

[_Pasha]

достойный аналог vsnprint()

xprintf?
Но допиливать - надо.
PS
в частности
в самом начале там есть static char *outptr
Какбы не очень...
Зато malloc() убит в зародыше!

Сообщение отредактировал _Pasha - Oct 16 2012, 18:35

[IgorKossak]

Если уж на то пошло посоветуйте достойный аналог vsnprint(). Вещественные числа не нужны, только целые со знаком и без и строки, и чтобы не пыталась выделять память без спроса

Как пример возьмите здесь.

[Cosmojam]

Спасибо за подсказки!
Но кажется проблема не в самой функции, а в va_arg.
Случайным поиском в сети нашёл http://www.menie.org/georges/embedded/printf-stdarg.html попробовал - тоже самое! В поведении ничего не поменялось.
Попробую ещё варианты функции, но что-то кажется не поможет.

По ходу надо делать syslog_write() с уже сформированной строкой на входе и оборачивать вызов в макрос где уже будет выделен буфер и вызван sprintf.

-=UPDATED=-
Как обычно по невнимательности ищу проблему не там где она есть.
В одной из задач (TCP клиент на сокетах lwip) была такая конструкция:

Код

        if(connect(sockfd, (struct sockaddr *)&serv_addr, sizeof(serv_addr)) < 0)
        {
            syslog_write(LOG_ERROR, pcTaskGetTaskName(NULL), "Cannot connect to %s:%u", serv_addr.sin_addr.s_addr, ntohs(serv_addr.sin_port));
.....

Задача эта периодически убивалась и создавалась и периодически не могла подключиться к серверу что приводило к вызову syslog_write(). Но я забыл обернуть serv_addr.sin_addr.s_addr в inet_ntoa() - ведь там не строка с IP-адресом, а целое число в структуре. Это и приводило к попытке обращения к адресу в памяти который на самом деле является IP-адресом сервера в виде 32-битного интеджера (то самое число 0x201A8C0 оседающее в BFAR если поменять порядок байт на сетевой получится 192.168.1.2 - адрес сервера).
TDD рулит

Сообщение отредактировал Cosmojam - Oct 16 2012, 20:02

[Terminator]

Стека хватает - к гадалке не ходи. Пробовал безумные размеры выделять где "640кб всем хватит"

Прям странно очень. Скорее всего где-то ошибаешься.

У меня по всем проектам понатыканы DBG(...) через sprintf (не библиотечный конечно), отлично работает.

[Cosmojam]

Прям странно очень. Скорее всего где-то ошибаешься.

У меня по всем проектам понатыканы DBG(...) через sprintf (не библиотечный конечно), отлично работает.

Не, всё нормально со стеком. Ошибаюсь наверное в том что этот буфер выделяется на стеке вызывающей функцию задачи => стек всех задач должен быть больше на размер буфера. Поскольку работа с буфером ведётся внутри критической секции, то лучше сделать буфер в bss, заменить критическую секцию на мьютекс и возвращать мьютекс после записи буфера в очередь

[Terminator]

Не, всё нормально со стеком. Ошибаюсь наверное в том что этот буфер выделяется на стеке вызывающей функцию задачи => стек всех задач должен быть больше на размер буфера.

Именно, а вы как думали?

Поскольку работа с буфером ведётся внутри критической секции, то лучше сделать буфер в bss, заменить критическую секцию на мьютекс и возвращать мьютекс после записи буфера в очередь

Если сильно надо экономить стек, то это поможет.