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 ★★★★★
()
Ответ на: комментарий от pon4ik

localtime_r() не поможет, tm-буфер отдельно лежит и на синхронизацию никак не влияет, это не его защищают (time/localtime.c в glibc).

xaizek ★★★★★
()
Последнее исправление: xaizek (всего исправлений: 1)
Ответ на: комментарий от 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 ★★★★★
()
Вы не можете добавлять комментарии в эту тему. Тема перемещена в архив.