Bug 27865

В реальности он не работает также если выполнить service ahttpd restart
Но работает если запустить ahttp -l (то есть без демонизации)
Чудеса.

Проблема где-то в районе ф-ции message-handler. Но что там происходит, почему влияет демонизация и почему все работает до service ahttpd restart - я не понимаю :(.

Точнее в response-handler при вызове with-ahttpd-session, похоже.

Будем посмотреть…

  Посмотрел. Там всё очень неважно: на первый взгляд кажется, что дело в самом guile. Например, после `service ahttpd restart` не работает вызов string-downcase (управление оттуда не возвращается), хотя она, извините, primitive-proc. Далее, let-values обрабатывается нормально, а let*-values — подвисает, не вычисляя ни один из своих аргументов. Однако эта гипотеза, скорее всего не верна, или не совсем верна, потому как даже в 5.1 версия guile у нас всё та же — 1.8.7, отличаются только alt-релизы. Выходит, проблема ещё глубже? Самое ужасное, что на моей системе после dist-upgrade проблема не воспроизводится.

(В ответ на комментарий №5)
> Самое ужасное, что на моей системе после dist-upgrade проблема не
> воспроизводится.

А что обновилось?

Created attachment 5612 [details]
Запуск ahttpd с демонизацией через start-stop-daemon

  Точно не знаю, что обновилось, но предлагаю подойти к проблеме немного с другой стороны.

  Перед тем, как увидел «что же там внутри», я был уверен, что дело в каком-нибудь файле, который не удаляется при перезапуске ahttpd. Но в явном виде проблем с файлами обнаружено не было. Что же получается? При первом после перезагрузки системы запуске, программа работает как положено, а при повторном подвисает в совершенно неожиданных местах.

  В связи с этим, предлагаю поймать первого пробегающего мимо архитектора Linux-систем и спросить у него, где может накапливаться разница между первым и вторым запуском демона. Именно демона, т.к. повторный запуск в foreground функционирует нормально.

  А пока никто мимо не пробежал и на вопрос не ответил, то, как оказалось, проблему можно обойти отказавшись от штатной демонизации, и положившись на start-stop-deamon (патч прилагается). В связи с этим, кстати, можно заключить, что guile «башню сносит» именно где-то в районе deamonize, которая определена где-то в недрах libguile-vhttpd…

(In reply to comment #8)
>   Точно не знаю, что обновилось, но предлагаю подойти к проблеме немного с
> другой стороны.
> 
>   Перед тем, как увидел «что же там внутри», я был уверен, что дело в
> каком-нибудь файле, который не удаляется при перезапуске ahttpd. Но в явном
> виде проблем с файлами обнаружено не было. Что же получается? При первом после
> перезагрузки системы запуске, программа работает как положено, а при повторном
> подвисает в совершенно неожиданных местах.

Если первый запуск ahttpd после загрузки был без демонизации, влияет ли это на последующий запуск с демонизацией?

>   В связи с этим, предлагаю поймать первого пробегающего мимо архитектора
> Linux-систем и спросить у него, где может накапливаться разница между первым и
> вторым запуском демона. Именно демона, т.к. повторный запуск в foreground
> функционирует нормально.

Возможно, демон не убивается до конца, или оставляет за собой файлы, влияющие на демонизацию.  Возможно, демонизация просто кривая, и работает только один раз.

>   А пока никто мимо не пробежал и на вопрос не ответил, то, как оказалось,
> проблему можно обойти отказавшись от штатной демонизации, и положившись на
> start-stop-deamon (патч прилагается). В связи с этим, кстати, можно заключить,
> что guile «башню сносит» именно где-то в районе deamonize, которая определена
> где-то в недрах libguile-vhttpd…

Демонизация с помощью start-stop-deamon - это костыль для убогих.
Отказываться от штатной демонизации имеет смысл только если вы запускаете ahttpd из systemd с помощью файла ahttpd.service, которого в пакете alterator-fbi не видно.

(В ответ на комментарий №9)
> (In reply to comment #8)
> Возможно, демон не убивается до конца,

  Процесса нет, я проверял.

> или оставляет за собой файлы, влияющие на демонизацию.

  Вроде нет таких.

>  Возможно, демонизация просто кривая, и работает только один раз.

  Она работает, но сам демон начинает глючить. И, возвращаясь к исходному вопросу, как можно сделать «один раз» не используя файлы? Т.е. откуда она может знать, что данный раз — не первый? :)

Припоминаются болтающиеся сегменты shm и IIRC семафоры; см. тж. 
http://lists.altlinux.org/pipermail/devel/2003-August/095235.html
http://lists.altlinux.org/pipermail/community/2001-August/440930.html

(In reply to comment #11)
> Припоминаются болтающиеся сегменты shm и IIRC семафоры; см. тж. 
> http://lists.altlinux.org/pipermail/devel/2003-August/095235.html
> http://lists.altlinux.org/pipermail/community/2001-August/440930.html

И очереди - в SysV IPC три типа объектов.  Инструмент для просмотра: ipcs(1).

  Решил углубиться ещё дальше.

guile/libguile/strings.c

 341 char *
 342 scm_i_string_writable_chars (SCM orig_str)
 343 {
 344   SCM buf, str = orig_str;
 345   size_t start;
 346 
 347   get_str_buf_start (&str, &buf, &start);
 348   if (IS_RO_STRING (str))
 349     scm_misc_error (NULL, "string is read-only: ~s", scm_list_1 (orig_str));
 350 
 351   scm_i_pthread_mutex_lock (&stringbuf_write_mutex);
 352   if (STRINGBUF_SHARED (buf))
 353     {
 354       /* Clone stringbuf.  For this, we put all threads to sleep.
 355        */
 356 
 357       size_t len = STRING_LENGTH (str);
 358       SCM new_buf;
 359 
 360       scm_i_pthread_mutex_unlock (&stringbuf_write_mutex);
 361 
 362       new_buf = make_stringbuf (len);
 363       memcpy (STRINGBUF_CHARS (new_buf),
 364               STRINGBUF_CHARS (buf) + STRING_START (str), len);
 365 
 366       scm_i_thread_put_to_sleep ();
 367       SET_STRING_STRINGBUF (str, new_buf);
 368       start -= STRING_START (str);
 369       SET_STRING_START (str, 0);
 370       scm_i_thread_wake_up ();
 371 
 372       buf = new_buf;
 373 
 374       scm_i_pthread_mutex_lock (&stringbuf_write_mutex);
 375     }
 376 
 377   return STRINGBUF_CHARS (buf) + start;
 378 }

 Блокировка (lock/unlock) отрабатывает нормально. Однако сон (sleep) одолевает, видимо, все процессы, включая текущий, что из логики кода вроде бы не следует.

 366       scm_i_thread_put_to_sleep ();

 Вот прямо тут и висим. Вообще про логику кода я немного поспешил: для начала её понять нужно. Лично меня вводит в ступор эдакая блокировка наизнанку, когда всё заканчивается lock. Обычно ведь блокировка кратковременна.

А в свежей guile 1.8.8 изменений тут нет?

(В ответ на комментарий №14)
> А в свежей guile 1.8.8 изменений тут нет?

  Сейчас посмотрим. Но вряд ли дело в том, что этот кусок безусловно кривой. Скорее, некоторое внешнее по отношению к guileПотому что:

  1. она давно (по крайней мере с 5.1) уже не обновлялась и всё работало;
  2. после dist-upgrade cert6 → Sisyphus всё продолжает работать (у меня).

  Т.е. мы имеем дело с чем-то, что делает работу guile нестабильной. Что это за обстоятельства — непонятно.

(В ответ на комментарий №14)
> А в свежей guile 1.8.8 изменений тут нет?

  Сейчас посмотрим. Но вряд ли дело в том, что этот кусок безусловно кривой. Скорее, некоторое внешнее по отношению к guile обстоятельство делает её работу нестабильной. Потому что:

  1. она давно (по крайней мере с 5.1) уже не обновлялась и всё работало;
  2. после dist-upgrade cert6 → Sisyphus всё продолжает работать (у меня);
  3. при запуске из консоли всё работает;
  4. с демонизацией через start-stop-daemon всё работает.

  Что это за обстоятельство? В том-то и вопрос…

(В ответ на комментарий №14)
> А в свежей guile 1.8.8 изменений тут нет?

  Оказалось, что string.c сильно переработан. И sleep вообще нет. Так что новая сборка guile может помочь. Вот только получится ли?

(В ответ на комментарий №17)
> (В ответ на комментарий №14)
> > А в свежей guile 1.8.8 изменений тут нет?
> 
>   Оказалось, что string.c сильно переработан. И sleep вообще нет. Так что новая
> сборка guile может помочь. Вот только получится ли?

  Только это оказалась не 1.8.8, а самая свежая версия.

  Подумал было, что при локальном запуске вот этот кусок

 352   if (STRINGBUF_SHARED (buf)) {
       ...
       }

просто не выполняется. Ан нет: выполняется. И scm_i_thread_put_to_sleep тоже. Просто не виснет.

  Вообще, как мне кажется, основополагающей следует считать проблему воспроизведения данной ошибки. У меня не получается вручную сделать систему, на которой она бы воспроизводилась:

  1. после dist-upgrade проблемы не наблюдается (Сизиф);

  2. после update-kernel -t std-def проблемы не наблюдается (3.5.7-std-def-alt1);

  3. после установки всех модулей alterator-*, установленных на проблемной машине, проблема по прежнему не наблюдается.

  Ещё идеи?

(В ответ на комментарий №20)
>   Вообще, как мне кажется, основополагающей следует считать проблему
> воспроизведения данной ошибки. У меня не получается вручную сделать систему, на
> которой она бы воспроизводилась:

У меня на машине не воспроизводится и не воспроизводилось и ранее (Сизиф). Воспроизводится в KVM на сборке дистрибутива на Сизифе конца сентября. Могу сделать там dist-upgrade до текущего Сизифа и проверить еще раз.

> У меня на машине не воспроизводится и не воспроизводилось и ранее (Сизиф).
> Воспроизводится в KVM на сборке дистрибутива на Сизифе конца сентября. Могу
> сделать там dist-upgrade до текущего Сизифа и проверить еще раз.
У меня воспроизводится 100% при установке образов свежего кентавра в kvm.

(В ответ на комментарий №22)
> У меня воспроизводится 100% при установке образов свежего кентавра в kvm.

А кто-нибудь вообще видел этот баг не в kvm?

Баг проявился после установки systemd!

Внимание вопрос: можем ли мы убрать из кода демонизацию, когда стартуем из-под systemd на готовом сокете? Тогда всё работает.

(In reply to comment #24)
> Баг проявился после установки systemd!
> 
> Внимание вопрос: можем ли мы убрать из кода демонизацию, когда стартуем из-под
> systemd на готовом сокете? Тогда всё работает.

При запуске средствами systemd вам не нужна демонизация.

(В ответ на комментарий №23)
> А кто-нибудь вообще видел этот баг не в kvm?
В Virtualbox новый Кентавр вообще не работает.

(В ответ на комментарий №24)
> Баг проявился после установки systemd!

У меня воспроизводится и без systemd (в kvm).

> Внимание вопрос: можем ли мы убрать из кода демонизацию, когда стартуем из-под
> systemd на готовом сокете? Тогда всё работает.

Это, конечно, здорово, но у нас еще предполагается выпуск дистрибутивов без systemd. Так что разбираться все равно надо.

(В ответ на комментарий №26)
> > А кто-нибудь вообще видел этот баг не в kvm?
> В Virtualbox новый Кентавр вообще не работает.

Я в первую очередь имел в виду на реальном железе.

  Прошу проверить отдельно на дистрибутиве с systemd и без оного:

http://git.altlinux.org/tasks/84795

(В ответ на комментарий №28)
>   Прошу проверить отдельно на дистрибутиве с systemd и без оного:
> 
> http://git.altlinux.org/tasks/84795
без systemd:
[root@c212 ~]# service ahttpd start
Starting ahttpd service: ERROR: no code for module (alterator systemd)
                                                                                                                  [FAILED]
[root@c212 ~]#  ЖЖесть :D

  А, точно, зависимость на новый alterator нужна. Спасибо. :)

(В ответ на комментарий №29)
> (В ответ на комментарий №28)
> >   Прошу проверить отдельно на дистрибутиве с systemd и без оного:
> > 
> > http://git.altlinux.org/tasks/84795
Надо добавить в alterator-fbi версионированную зависимость на alterator.

без systemd в kvm: после обновления ahhtpd не поднялся, потом, после того, как я обновил alterator, поднялся и нормально заработал.
После restart опять не работает.
После stop; sleep 60;start по прежнему не работает, так что, видимо, дело тут не во времени, прошедшем между остановкой и запуском...

service ahttpd stop
service alteratord restart
service ahttpd start

Да это kvm, но это очень важная для нас тестовая платформа.

  После переключения назад на SysV-init у мня, по прежнему, не воспроизводится. Предлагаю обменяться виртуалками.

alterator-fbi-5.28-alt1 -> sisyphus:

* Thu Nov 22 2012 Paul Wolneykien <manowar@altlinux> 5.28-alt1
- Do not daemonize in socket-activation mode (closes: 27865).
- Add the systemd unit files.
- Start the server on the given socket if any (closes: 27987).

Спасибо!

Я не вижу чтобы что-то изменилось.

  А я не могу воспроизвести при загрузке без systemd. В том же контейнере.

(В ответ на комментарий №32)
>   После переключения назад на SysV-init у мня, по прежнему, не воспроизводится.
> Предлагаю обменяться виртуалками.

c212 в офиссной сети.

  Залёз ещё глубже. Как в общем-то и предполагалось, повисаем в ожидании семафора (некий heap_mutex).

1626		scm_i_pthread_mutex_lock (&t->heap_mutex);
…
pthread_mutex_lock (mutex=mutex@entry=0x7fb260000940) at forward.c:192

  Полагаю, есть два реалистичных варианта решения:

  1. попытаться разобраться в танцах с семафорами и, если это deadlock, придумать патч, его устраняющий;

  2. детектить kvm и, если работаем под kvm и без systemd, использовать «костыль для убогих» — демонизацию в start-stop-daemon. Только в этом случае. В остальных же случаях всё и так работает (я прав?).

(In reply to comment #38)
>   Залёз ещё глубже. Как в общем-то и предполагалось, повисаем в ожидании
> семафора (некий heap_mutex).
> 
> 1626        scm_i_pthread_mutex_lock (&t->heap_mutex);
> …
> pthread_mutex_lock (mutex=mutex@entry=0x7fb260000940) at forward.c:192
> 
>   Полагаю, есть два реалистичных варианта решения:
> 
>   1. попытаться разобраться в танцах с семафорами и, если это deadlock,
> придумать патч, его устраняющий;
> 
>   2. детектить kvm и, если работаем под kvm и без systemd, использовать
> «костыль для убогих» — демонизацию в start-stop-daemon. Только в этом случае. В
> остальных же случаях всё и так работает (я прав?).

Так как причин, почему такое происходит именно с kvm (да и только ли с kvm?) мы не нашли, то, полагаю, остается первый вариант.
2boyarsh: что думаете?

> Так как причин, почему такое происходит именно с kvm (да и только ли с kvm?) мы
> не нашли, то, полагаю, остается первый вариант.
> 2boyarsh: что думаете?
Я думаю, что можно всегда использовать демонизацию в start-stop-daemon, раз она работает надёжно.

  Этот путь труден тем, что явной баги в коде, скорее всего нет, поскольку в большинстве случаев он же работает. А значит всё равно в результате, скорее всего, будет костыль.

  Мы с тобой синхронно отписались. :) Но я имел в виду правку кода, а не start-stop-daemon.

(In reply to comment #40)
> > Так как причин, почему такое происходит именно с kvm (да и только ли с kvm?) мы
> > не нашли, то, полагаю, остается первый вариант.
> > 2boyarsh: что думаете?
> Я думаю, что можно всегда использовать демонизацию в start-stop-daemon, раз она
> работает надёжно.

Ok.

  А я нашёл разницу в выполнении кода между первым разом и последующим (после перезагрузки). Правда эта разница уже за пределами собственно guile, в pthreads.

  Если пока не вдаваться в подробности, то мы имеем, видимо deadlock: кто-то держит семафор (mutex->__data.__nusers == 1). Логично предположить, что этот кто-то — это тень отца Гамлета ^W^W предыдущего запуска ahttpd.

  Внимание вопрос: а нет ли какого-нибудь приёма для опускания всех pthreads-семафоров, задействованных в программе и порождённых процессах? Мы бы тогда использовали его при перезагрузке ahhtpd (где-нить в exit-handler).

  Чтобы дальше разбираться с этой багой, нужно понять одну принципиальную вещь: после остановки служб процесс guile18 в явном виде отсутствует (ps auxww | grep 'guile18' не находит ни одного экземпляра), как же тогда mutex->__data.__nusers == 1 ? Мне казалось, что раз mutex — это всё-таки переменная, то она должна исчезать вместе с освобождением памяти при завершении процесса. Это не так?
  Второй вариант, кончено, может быть таким, что при повторном запуске данный семафор явно устанавливается, но совсем из другого участка кода, а не из того, который я отлаживаю. Это я ещё не проверял.

(В ответ на комментарий №46)
> Мне казалось, что раз mutex — это всё-таки переменная, то она должна
> исчезать вместе с освобождением памяти при завершении процесса. Это не так?
Теоретически mutex может быть размещён в разделяемой памяти, тогда в случае правильного использования pthread_mutexattr_setpshared() он может совместно использоваться несколькими процессами. Если же mutex размещается в обычной памяти, блокировать его некому, кроме потоков того процесса, в памяти которого находится mutex.

  Спасибо за комментарий, Сергей. А что вы скажете на это?

# service ahttpd restart

# ps auxww | grep 'guile18'
_ahttpd   8534  0.0  1.1 148932  6012 ?        ts   18:03   0:00 /usr/bin/guile18 -s /usr/sbin/ahttpd

# gdb /usr/bin/guile18 8534
…
…
(gdb) p t->heap_mutex
$1 = {__data = {__lock = 1, __count = 0, __owner = 8533, __nusers = 1, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}}, 
  __size = "\001\000\000\000\000\000\000\000U!\000\000\001", '\000' <repeats 26 times>, __align = 1}

  После перезагрузки ahttpd, heap_mutex уже оказывается занят. Но что особо интересно, занят он процессом с ID ровно на 1 меньшим, чем ahttpd. Я делаю вывод, что это — родительский процесс. Не предыдущий экземпляр ahttpd, а именно родитель, порождающий демона (как страшно звучит, однако…). Видимо этот родитель успевает зажать mutex, и не отпускает его. Почему этого не происходит при первичном запуске службы остаётся загадкой.

  Собственно, workaround найден:

  # diff /usr/sbin/ahttpd{~,}
250c250,252
< 	     (daemonize (config-ref *config* "server-pidfile")))
---
> 	     (begin
> 	       (sleep 5)
> 	       (daemonize (config-ref *config* "server-pidfile"))))

  Т.е. если немного обождать перед отпачковыванием, то в порождаемом процессе mutex не будет занят, но будет свободен. Что это, в теории, значит?

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

(В ответ на комментарий №48)
> # ps auxww | grep 'guile18'
> _ahttpd   8534  0.0  1.1 148932  6012 ?        ts   18:03   0:00
> /usr/bin/guile18 -s /usr/sbin/ahttpd

Проверьте ещё на всякий случай вывод такой команды:

  ps axH -Olwp | grep 'guile18'

(без опции H ps показывает только одну строку для процесса независимо от количества потоков в этом процессе).

>   После перезагрузки ahttpd, heap_mutex уже оказывается занят. Но что особо
> интересно, занят он процессом с ID ровно на 1 меньшим, чем ahttpd. Я делаю
> вывод, что это — родительский процесс. Не предыдущий экземпляр ahttpd, а именно
> родитель, порождающий демона (как страшно звучит, однако…). Видимо этот
> родитель успевает зажать mutex, и не отпускает его. Почему этого не происходит
> при первичном запуске службы остаётся загадкой.
Значит, демонизация реализована неправильно (выполняется fork() при захваченном mutex, в результате потомок не может освободить этот mutex, поскольку у потомка уже другой идентификатор). Вообще pthread и fork() очень плохо совмещаются в одном процессе (единственный относительно надёжно работающий вариант — если после fork() в порождённом процессе как можно быстрее делается execve() или _exit(); теоретически возможен объезд через pthread_atfork(), но реализовать его без ошибок очень сложно).

я смутно помню, что с демонизацией внутри guile были проблемы ещё несколько лет
назад, выражались в пропаже локализации (кажется) на одной из x86 (i586 или x86_64), тогда же был найден ровно этот же workaround -- использовать
s-s-d. Удивительно по прошествии нескольких лет видеть что-то подобное снова.

Похоже, демонизация из процесса, использующего guile, действительно не должна работать:

http://lists.gnu.org/archive/html/guile-devel/2012-02/msg00062.html

Если невозможность обнаружить ошибку инициализации при демонизации через start-stop-daemon настолько критична, можно сделать отдельную программу запуска на C, которая будет выполнять pipe(), fork()/exec*() и получать от основного процесса результат его инициализации через pipe; при этом в процессе сервера по-прежнему могут выполняться все действия по созданию pid-файла, переназначению stdin/out/err после инициализации и т.д., кроме fork().

Резюмирую:
- демонизация средствами guile, собранным с поддержкой threads, нормально работать не будет, скорее всего, никогда;
- в systemd демонизация не нужна в принципе, имеющийся ahttpd.service реализует service type simple;
- в sysvinit остается применить костыль для убогих от s-s-d (start_daemon --make-pidfile, который вызывает start-stop-daemon --background --make-pidfile).

Дал права на пакет manowar@

alterator-fbi-5.28-alt3 -> sisyphus:

* Wed Nov 28 2012 Paul Wolneykien <manowar@altlinux> 5.28-alt3
- Use "a wretched-man's crutch" daemonization: start-stop-daemon
  for SysV-init (closes: 27865).