LINUX.ORG.RU

Почему может зависнуть вызов localtime()?

 ,


2

4

Есть такая замечательная софтина xrdp. И есть в ней такой замечательный код логгирования:

enum logReturns DEFAULT_CC
log_message(const enum logLevels lvl, const char *msg, ...)
{
    char buff[LOG_BUFFER_SIZE + 31]; /* 19 (datetime) 4 (space+cr+lf+\0) */
    va_list ap;
    int len = 0;
    enum logReturns rv = LOG_STARTUP_OK;
    int writereply = 0;
    time_t now_t;
    struct tm *now;

    if (g_staticLogConfig == NULL)
    {
        g_writeln("The log reference is NULL - log not initialized properly");
        return LOG_ERROR_NO_CFG;
    }

    if (0 > g_staticLogConfig->fd && g_staticLogConfig->enable_syslog == 0)
    {
        return LOG_ERROR_FILE_NOT_OPEN;
    }

    now_t = time(&now_t);
    now = localtime(&now_t);

Так вот, ИНОГДА, при неизвестных обстоятельствах, когда одновременно открывается много сессий, вызов now = localtime(&now_t); наглухо зависает. При этом bt в gdb показывает следующее:

(gdb) bt
#0  __lll_lock_wait_private () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:95
#1  0x00007f8a100bbabc in _L_lock_2480 () from /lib/x86_64-linux-gnu/libc.so.6
#2  0x00007f8a100bb8f7 in __tz_convert (timer=0x7f8a103c9ee0 <tzset_lock>, use_localtime=1, tp=0x7f8a103ccde0 <_tmbuf>) at tzset.c:627
#3  0x00007f8a10a1441b in log_message (lvl=LOG_LEVEL_INFO, msg=0x7f8a10a1b180 "An established connection closed to endpoint: %s") at log.c:556
#4  0x00007f8a10a1532d in g_tcp_close (sck=9) at os_calls.c:678
#5  0x0000000000405976 in session_start_fork (width=1024, height=768, bpp=24, username=0x7f8a08004a30 "xxx", 
    password=0x7f8a08004a60 "xxx", data=140230816451248, type=1 '\001', domain=0x0, program=0x0, directory=0x0, 
    client_ip=0x7f8a08004a80 "123.0.0.123:59517 - socket: 9") at session.c:523
#6  0x0000000000406bc0 in session_sync_start () at session.c:907
#7  0x00000000004041a5 in sesman_main_loop () at sesman.c:100
#8  0x0000000000404a84 in main (argc=1, argv=0x7fff8cb123d8) at sesman.c:393
(gdb) 

Из-за чего это может быть (сразу скажу, что код в этом месте не многопоточный, хотя форкается куча процессов)?

Система - Ubuntu 14.04. xrdp - 0.9 из git master.

UPD:

(gdb) info threads 
  Id   Target Id         Frame 
* 1    Thread 0x7f891182f740 (LWP 13555) "xrdp-sesman" __lll_lock_wait_private () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:95
(gdb) 


Последнее исправление: asaw (всего исправлений: 2)
Ответ на: комментарий от pon4ik

Ещё нет) Я ничего лучше не придумал, чем первым же делом написать сюда. А тыкать пальцем в небо тоже не хочется.

asaw
() автор топика
Ответ на: комментарий от pon4ik

Так баг то плавающий. Он то есть, то нет. Я сейчас поменяю, он пропадет, а потом окажется, что это была случайность.

Потом, интересно понять что это за лок такой и почему на нём всё зависает.

asaw
() автор топика
Ответ на: комментарий от asaw

Я мельком взглянул на код tzset.c, я не силён в сорцах glibc, но похоже, там лок на глобальный статический обьект в шарной либе.

После форка, адресное пространство хоть и cow, однако дескрипторы остаются все те же как и права на них. Поэтому это вполне может быть dead lock на этом «мьютексе».

Вообщем попробуй воспроизвести раз 10. Посчитай сколько попыток затратил. А потом на том же конфиге попробуй воспроизвести с localtime_r, за то же количество попыток.

Может патч пришлёшь этим негодникам использующим небезопасное дрвенее уг.

pon4ik
()
Ответ на: комментарий от asaw

А не пробовал смотреть ulimit в момент зависания? Может где-то что-то исчерпалось?

Radjah 👍
()
Ответ на: комментарий от pon4ik

Да, понятно, что там как минимум не будет обращения к коду tzset - уже хорошо...

asaw
() автор топика
Ответ на: комментарий от joy4eg

Ну, там уже некий патлатый тип в процессе же :)

Вообще не знал что это known issue. Про лок - знал, про смертельный не знал. В своё время, что бы не спать на таком локе (из соображений производительности) была запиленна либа, которая так то сию проблему решает, т.к. лока там нет в принципе :)

pon4ik
()
Ответ на: комментарий от joy4eg

Конкретно это нагуглил. Но там же ничего нет про дедлок, только про какие-то издержки, которые меня в данном случае не интересуют.

asaw
() автор топика
Ответ на: комментарий от asaw

Там же по ссылке есть workaroud - localtime_safe(). Если баг будет вылазить слишком часто, то можно и заюзать. Или бери либу от pon4ik и не мучайся :)

joy4eg
()
Ответ на: комментарий от xaizek

But the state of all mutexes, condvars and other objects are copied
into the child process «as is» and should be reinitialized

Дык и я об чём. Прост выражаюсь кривовато.

Есть даже служебные коллбэки которые можно глобально процессу выставить, что бы дёргались в процессе форка. Вот этот тип. На одной из лекций рассказывает как ими пользоваться.

pon4ik
()
Последнее исправление: pon4ik (всего исправлений: 1)
Ответ на: комментарий от xaizek

Честно говоря, не совсем убедительное объяснение:

gmtime_r() is not an async-signal-safe function, and therefore should not be called after a fork in a multithreaded application.

Дело в том, что fork-то есть, но не в multithreaded application.

(gdb) info threads 
  Id   Target Id         Frame 
* 1    Thread 0x7f891182f740 (LWP 13555) "xrdp-sesman" __lll_lock_wait_private () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:95
(gdb) 

Кроме того,

NOTES
       The four functions asctime(), ctime(), gmtime() and localtime() return a pointer to static data and hence are not thread-safe.  Thread-safe  versions  asc‐
       time_r(), ctime_r(), gmtime_r() and localtime_r() are specified by SUSv2, and available since libc 5.2.5.

- ничего не говорит про fork()...

asaw
() автор топика
Ответ на: комментарий от asaw

Вот тебе кейс когда случается смертельный запор:

пусть стейт мьютекса просто флаг 1/0.

  • Полез в localtime
  • Поспал пока Мьютекс == 1
  • Мьютекс = 1
  • Форк из другого потока
  • Родитель: сделал дело Мьютекс = 0
  • Ребёнок: полез в localtime ...

Под localtime, тут подходит любая функция использующая базу данных таймзон в памяти.

pon4ik
()
Последнее исправление: pon4ik (всего исправлений: 1)
Ответ на: комментарий от pon4ik

Получается, что по этой логике, если я заменю localtime на localtime_r, я рискую наступить на те же грабли с примитивами синхронизации...

asaw
() автор топика
Ответ на: комментарий от asaw

Тобишь - достаточно что бы форк произошёл из другого потока. Может быть есть ещё варианты, но тут я не уверен. Притом, нашалившим многопоточным родителем может быть как bash так и твой терминал.

pon4ik
()
Ответ на: комментарий от asaw

Дело в том, что fork-то есть, но не в multithreaded application.

Там futex'ы и я не знаю, раздваиваются ли как-то они при форке или нет.

ничего не говорит про fork()...

thread-safe ещё не значит, что можно вызывать после форка.

xaizek
()
Последнее исправление: xaizek (всего исправлений: 1)
Ответ на: комментарий от asaw

Получается что так, хм. Но тут лучше посмотреть сорцы, может там глобальный стейт не захватывается, или захватывается но другой или захватывается на запись только очень редко.

pon4ik
()
Ответ на: комментарий от xaizek

Ну пусть тогда переводит проект на libdt :D Только как fallback там всё равно используется localtime_r, однако, если перед этим вычислить локальную таймзону, то локов - не будет, заработает праведная реализация.

pon4ik
()
Ответ на: комментарий от pon4ik

а лучше - что не использует glibc :)

Как сказать. В musl похожее поведение, все эти локи из-за TZ, который может быть изменен из разных потоков, и перед тем как, собственно, конвертировать время оно делает tzset() который и есть корень всех зол, в данном случае.

joy4eg
()
Ответ на: комментарий от joy4eg

Вообще, учитывая что это просто логи - Я б забил и просто не вызывал localtime() а просто выводил текущие время как обычный unix time.

joy4eg
()
Ответ на: комментарий от pon4ik

Так проблема в том, что связи такого рода не видно. Если нет потоков, то на момент форка лок освобождён. А ядерных объектов то и нету (futex что-то хранит, но только на время вызова). Т.е. у ребёнка всё своё и он не должен никак пересекаться по синхронизации с родителем. Но вообще в коде там есть и потоки, может они просто завершились.

xaizek
()
Ответ на: комментарий от asaw

Кстати, это же один поток в дочернем процессе, а проблема в потоках родительского процесса на момент вызова fork().

xaizek
()
Ответ на: комментарий от xaizek

Да-да, и это делает всю картину гораздо печальнее. Потому что в том же log_message есть вызовы, например, syslog, а эта функция тоже не async-safe. С другой стороны, если заставить fork() (гипотетически) клонировать и все потоки тоже, то не факт, что сам xrdp будет правильно при этом работать. В общем, пока не понятно что делать.

asaw
() автор топика
Ответ на: комментарий от xaizek

Это devel- ветка, то есть, вроде как, нестабильная, а я смотрю в master. Там, вроде как, sessman у них тоже однопоточный, но есть там такой вот чудесный кусок в main():

/* initializing locks */
    lock_init();

    /* signal handling */
    g_pid = g_getpid();
    /* old style signal handling is now managed synchronously by a
     * separate thread. uncomment this block if you need old style
     * signal handling and comment out thread_sighandler_start()
     * going back to old style for the time being
     * problem with the sigaddset functions in sig.c - jts */
#if 1
    g_signal_hang_up(sig_sesman_reload_cfg); /* SIGHUP  */
    g_signal_user_interrupt(sig_sesman_shutdown); /* SIGINT  */
    g_signal_kill(sig_sesman_shutdown); /* SIGKILL */
    g_signal_terminate(sig_sesman_shutdown); /* SIGTERM */
    g_signal_child_stop(sig_sesman_session_end); /* SIGCHLD */
#endif
#if 0
    thread_sighandler_start();
#endif

https://github.com/neutrinolabs/xrdp/blob/master/sesman/sesman.c

То есть thread_sighandler_start(); они, всё же, решили не использовать, потому что наступили на какие-то грабли, зато вовсю используют свой log_message из обработчиков сигналов, того же sig_sesman_session_end() например. И в итоге хоть код и не многопоточный, эффекты с примитивами синхронизации могут быть теми же. Удивительно как из самих сигналов всё не лочится.

Интересно, можно ли что-нибудь сделать с log_message(), чтобы оно стало безопасно?

asaw
() автор топика
Последнее исправление: asaw (всего исправлений: 1)
Ответ на: комментарий от asaw

Интересно, можно ли что-нибудь сделать с log_message(), чтобы оно стало безопасно?

Просто удалить вызов localtime(), не?

joy4eg
()
Ответ на: комментарий от asaw

Да, но что делать с вызовом syslog()?

Страдать, вот, например, еще один баг.
А если серьезно - то или выкинуть его тоже, или сделать свою localtime() и подгружать её.

joy4eg
()
Ответ на: комментарий от joy4eg

Кстати, сами же сигналы можно заблокировать, либо пользовать signalfd, который будет работать в текущем потоке, и не будет прерывать выполнение программы.

joy4eg
()
Ответ на: комментарий от xaizek

Если потоки завершились - то соответсвенно и локи они освободили (если говорить конкретно про этот набор функций).

А вот если, например, навороченный мега терминал ТС имеет свой лог, с таймштампами, в отдельном потоке то тут уже могут наблюдаться свистопляски. А если он пускает её из какого нить unity, то вероятность что подобное поведение имеет место быть =>99.99% :)

А может, он просто терминал вызвал в неудачное время.

Единственное что меня смущает во всех этих умозаключениях - проблема воспроизводится нестабильно. Но если пускается из гуя то это только подтверждает теории выше.

pon4ik
()
Ответ на: комментарий от pon4ik

exec() все побочные эффекты должен убирать. Тут проблема именно в том, что сам xrdp-sesman себя форкает по нескольку раз...

asaw
() автор топика
Последнее исправление: asaw (всего исправлений: 1)
Ответ на: комментарий от asaw

вообще, логирование откуда попало (в том числе с вызовами функций работы с датами) - плохая идея. очереди сообщений и отдельный обработчик на высер всего накопленного в логи и т.д.

Iron_Bug ☕☕☕☕☕
()
Ответ на: комментарий от Iron_Bug

А мне-то всегда казалось, что как раз именно логгеры должны быть реализованы таким образом, чтобы их можно было безопасно дергать откуда угодно. Ведь они нужны для диагностики проблем, а не для создания новых)

asaw
() автор топика
Ответ на: комментарий от asaw

ну, для обычного приложения это так. но стоит хоть чуть-чуть отойти от массового программирования в сторону чего-то более замысловатого, и сразу уже приходится работать вручную. вообще, мы во всех проектах свои логгеры делали. это не так затратно, зато надёжно. а уж куда потом срать из лога - дело десятое. впрочем, можешь попробовать форкнуть syslog и решить проблему в корне :) я думаю, у них тоже были какие-то тараканы на этот счёт, раз они не стали обеспечивать абсолютную безопасность вызовов.

Iron_Bug ☕☕☕☕☕
()
Ответ на: комментарий от asaw

зато вовсю используют свой log_message из обработчиков сигналов

В этом, я так понимаю и есть главный фейл разработчиков этой программы.

pathfinder
()
Ответ на: комментарий от pathfinder

Интересно, что я при этом ни разу не видел зависания в каком-нибудь обработчике сигнала... Но, видимо, так и есть.

asaw
() автор топика

тоже сталкивался с такой хренью, прога была без потоков вообще, но тем неменее случайно как то по рандому висло на localtime, разбираться было лень, вставил localtime_r зависания ушли, перечитав весь топик подумаю уйти на localtime_safe, только хз что делать с таймзоной, она тоже нужна мне в некоторых функционалах

anonymous
()
Ответ на: комментарий от pon4ik

pon4ik, хотел вот поинтересоваться: эта библиотека - libdt - точно reentrant? Почему спрашиваю: нашел внутри вызовы функций вроде strftime(), относительно которых таких гарантий, вроде бы, нет. И точно не гарантируется async-signal safety, чего мне бы хотелось.

asaw
() автор топика
Ответ на: комментарий от asaw

Там должно быть в доке к функциям записанно кто reentrant а кто нет. Алгебра и снятие времени там точно глобального записываемого стейта не несёт, если несёт - это бага.

pon4ik
()
Вы не можете добавлять комментарии в эту тему. Тема перемещена в архив.