[ЗАКРЫТО]Долгое завершение работы systemd.

шелл стандартный /bin/bash, диски разбиты стандартно, вся система на одном харде. Содержимое юнита идентично вашему. Насколько я помню можно вывести ещё более подробный лог касательно отдельного юнита, сейчас в манах гляну, как это можно сделать...
root@vpupkin# cat /dev/ass > /dev/head
Так, я стал ближе к разгадке, кто подскажет, почему systemd не может открыть приватное соединение D-Bus для юнита user@1000.service? Вот вывод команды:
$ journalctl -u user@1000.service --since=00:00 --until=9:30
янв 03 00:04:23 bigboyuser systemd[919]: Failed to open private bus connection: Failed to connect to socket /run/user/1000/dbus/user_bus_socket
янв 03 00:04:23 bigboyuser systemd[919]: Mounted /sys/kernel/config.
янв 03 00:04:23 bigboyuser systemd[919]: Mounted /sys/fs/fuse/connections.
янв 03 00:04:23 bigboyuser systemd[919]: Stopped target Sound Card.
янв 03 00:04:23 bigboyuser systemd[919]: Starting Default.
янв 03 00:04:23 bigboyuser systemd[919]: Reached target Default.
янв 03 00:04:23 bigboyuser systemd[919]: Startup finished in 59ms.
янв 03 00:05:32 bigboyuser systemd[919]: Stopping Default.
янв 03 00:05:32 bigboyuser systemd[919]: Stopped target Default.
янв 03 00:05:32 bigboyuser systemd[919]: Starting Shutdown.
янв 03 00:05:32 bigboyuser systemd[919]: Reached target Shutdown.
янв 03 00:05:32 bigboyuser systemd[919]: Starting Exit the Session...
янв 03 00:05:32 bigboyuser systemd[919]: systemd-exit.service: main process exited, code=exited, status=200/CHDIR
янв 03 00:05:32 bigboyuser systemd[919]: Failed to start Exit the Session.
янв 03 00:05:32 bigboyuser systemd[919]: Dependency failed for Exit the Session.
янв 03 00:05:32 bigboyuser systemd[919]: Unit systemd-exit.service entered failed state.
root@vpupkin# cat /dev/ass > /dev/head
Кто нибудь может объяснить что происходит здесь
янв 03 00:04:23 bigboyuser systemd[919]: Starting Default.
Что там так долго стартует и останавливается?
Гляньте на всякий случай - какие сервисы у вас активированы и какие завершились с ошибками (systemctl --failed). Все с правами рута конечно.
Sheykhnur
systemctl --global enable dbus.socket
https://wiki.archlinux.org/index.php/Systemd/User
Ошибки в тексте-неповторимый стиль автора©
@vadik, результат выполнения команды
#systemctl --failed
0 loaded units listed. Pass --all to see loaded but inactive units, too.
To show all installed unit files use 'systemctl list-unit-files'.
@ind.indeviral, спасибо, ваш совет помог избавиться от ошибок типа
Failed to open private bus connection: Failed to connect to socket /run/user/1000/dbus/user_bus_socket
, но проблему, к сожалению, не решил :-((
Ладно, всем огромнейшее спасибо, кто помогал и направлял, на сегодня хватит, через сутки возобновлю искания. Быстрее было бы переустановить систему, но мы же не ищем лёгких путей :-) Просто удивительно, почему в режиме debug всё равно так мало информации в журнале! Знать бы, что он делает между
[  190.351537] systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
и
[  197.919468] systemd[1]: user@1000.service stopping timed out. Killing.
вот тогда бы всё и выяснилось! Ещё раз всем спасибо, тему не закрываю, но, видимо придётся самому копать; о результатах отпишусь.
root@vpupkin# cat /dev/ass > /dev/head
Долго отсутствовал, может пригодится создание лога завершения работы.
1. Создаем скрипт, например debug.sh, в /lib/systemd/system-shutdown/
#!/bin/sh
mount -o remount,rw /
dmesg > /var/log/shutdown.log
mount -o remount,ro /
2. Делаем его исполняемым.
3. При перезагрузке в строке запуска пишем
systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M
Если этого не сделать, то лог завершения будет не информативным — всего около 10 строк.
4. Анализируем файл /var/log/shutdown.log
Начало завершения — ищем строку типа systemd[1]: Stopping Session 1 of user …такой-то.....
(в начале будет идти дата и время, если что тормозит, смотрим на время).
Ошибки не исчезают с опытом - они просто умнеют
Sheykhnur
Просто удивительно, почему в режиме debug всё равно так мало информации в журнале!
Для этого нужно использовать debug-shell + добавить в параметрах запуска systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M
UPD.......... но это полезно в том случае, если зависание произошло после приветствия ArchLinux (то есть после запуска systemd).
PS...... хотя, возможно, я и не прав - никогда не сравнивал информативность логов с использованием debug-shell в работающей системе. Поэтому, думаю, достаточно просто опции systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M
Ошибки не исчезают с опытом - они просто умнеют
Sheykhnur
Знать бы, что он делает между
[ 190.351537] systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
и
[ 197.919468] systemd[1]: user@1000.service stopping timed out. Killing.
вот тогда бы всё и выяснилось!

Попробовал добавить информативности в логи. Вот что получил.
1. Обычная загрузка
$ journalctl -b | grep 'Got D-Bus'
….......ничего нет..............
2. Загрузка с увеличением информативности
$ journalctl -b | grep 'Got D-Bus'
янв 07 17:29:12 arch systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Agent.Released() on /org/freedesktop/systemd1/agent
янв 07 17:29:12 arch systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/Dbus/Local
…..........много повторений.............
янв 07 17:29:13 arch systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.Get() on /org/freedesktop/systemd1
…....................................
янв 07 17:29:36 arch systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.StartUnit() on /org/freedesktop/systemd1
….......................................
Так что попробовать стоит. Будет увеличение информативности и в логе завершения работы.
Ошибки не исчезают с опытом - они просто умнеют
Vasek, спасибо. Честно говоря, эти дни не было времени подолгу разбираться в проблеме, но кое-что я всё-таки выяснил. Для начала, как вы помните дебаг журнала с целью kmesg я сделал уже давно, ещё в первом посту :-) За эти несколько дней я немного стал разбираться с systemd, подучил английский и понял одну вещь: информативность логов напрямую зависит от общительности служб)
янв 07 17:29:36 arch systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.StartUnit() on /org/freedesktop/systemd1
это всё конечно лучше, чем ничего, но всё же мало. Что за юнит стартовал через D-Bus? Какие сообщения он получил? Когда? В общем с логгированием пока всё ещё темно. Да и user-session пока ещё на стадии тестирования (спасибо ind.indeviral за наводку).
Теперь по теме. Как выяснилось, тормозит какая-то пользовательская служба, ибо когда я вручную завершаю графический сеанс и выхожу из пользовательской сессии, а потом вхожу под рутом, то завершается быстро. Так вот, когда я уже под рутом (из пользователя вышел), то в списке процессов вижу какой-то ещё не завершившийся процесс из под пользователя. Сдаётся мне он и есмь виновник, т.к. после его завершения из под рута система выключается как и положено, т.е. быстро. Из-за нехватки места на экране пока не разглядел, что это за процесс, но это, в принципе решаемо. И ещё: в процессе user@1000.service загружены все пользовательские службы, т.к. этот процесс, по сути, является пользовательской сессией (если не прав - поправьте, пожалуйста), что-то вроде svchost офтопика, только из под пользователя. Насколько я понял всё это дело управляется cgroup. Но сейчас не об этом. Как я уже выше отмечал этот процесс завершается с тайм аутом. Но, блин, это не он виноват, а оставшаяся служба внутри него, (как я это выяснил, читайте выше) т.к. он ждёт пока эта последняя служба завершится. Теперь вопрос: как выяснить, какой процесс не даёт службе завершиться? Инструменты для отслеживания загрузки в системд сделаны очень хорошо и даже наглядно, а вот с завершением пока не очень.
root@vpupkin# cat /dev/ass > /dev/head
Начало раньше читал невнимательно, так что зла не держи — написал много лишнего. Сейчас посмотрел логи
Sheykhnur
[ 3052.787778] systemd[1]: Accepted connection on private bus.
[ 3052.788106] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Agent.Released() on /org/freedesktop/systemd1/agent
[ 3052.788301] systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
[ 3140.375128] systemd[1]: user@1000.service stopping timed out. Killing.
[ 3140.375640] systemd[1]: user@1000.service changed stop-sigterm -> stop-sigkill
[ 3140.375691] systemd[1]: Received SIGCHLD from PID 898 (systemd).
[ 3140.375723] systemd[1]: Got SIGCHLD for process 898 (systemd)
[ 3140.375797] systemd[1]: Child 898 died (code=killed, status=9/KILL)
[ 3140.375803] systemd[1]: Child 898 belongs to user@1000.service
[ 3140.375814] systemd[1]: user@1000.service: main process exited, code=killed, status=9/KILL
Ты все правильно пишешь, user@1000.service не может правильно завершить работу.
timed out — грубо говоря, истекло максимальное время ожидания завершения процесса user@1000.service.
Sheykhnur
.....сервис не может завершить корректно работу, т.к. не получает сигнал d-bus.....
здесь с тобой не согласен. Система послала процессу user@1000.service сигнал SIGTERM для завершения процесса (именно этот сигнал предназначен для завершения процесса, и в штатной ситуации процесс, получивший этот сигнал, завершается), но процесс его проигнорировал и не завершился — поэтому и timed out, а после уже вынужденно stop-sigkill.
Подожди обновления systemd — может поправится.
UPD....имеется такая фича fuser — с помощью которой можно определить какой процесс держит открытым какой-то файл или сокет. Никогда не пользовался, подойдет не подойдет, не знаю. Почитай.
Ошибки не исчезают с опытом - они просто умнеют
 
Зарегистрироваться или войдите чтобы оставить сообщение.