Эта тривиальная задача возникла в один из пятничных дней и должна была занять 2-3 минуты времени. В общем, как всегда.
Коллега попросил поправить скрипт у него на сервере. Сделал, сдал ему и обронил ненароком: «Время спешит на 5 минут». Сервер его, пусть сам и разбирается с синхронизацией. Полчаса, час прошел, а он всё пыхтит и тихо матерится.
«Бестолочь! — подумал я, переключаясь в консоль сервера — ну ладно оторвусь ещё на пару минут.»
Смотрим, ntp, rdate, sdwdate не установлены, timesyncd отключен и не запущен.
# timedatectl
Local time: Sun 2019-08-25 20:44:39 +03
Universal time: Sun 2019-08-25 17:44:39 UTC
RTC time: Sun 2019-08-25 17:39:52
Time zone: Europe/Minsk (+03, +0300)
NTP enabled: no
NTP synchronized: no
RTC in local TZ: no
DST active: n/a
Здесь сразу отмечу, что аппаратное время верное: по нему будет легче ориентироваться дальше.
Отсюда и началась череда ошибок.
Ошибка первая. Самоуверенность
Клац-клац…
# systemctl enable systemd-timesyncd.service && systemctl start systemd-timesyncd.service && ntpdate 0.ru.pool.ntp.org && timedatectl set-ntp on && timedatectl
25 Aug 21:00:10 ntpdate[28114]: adjust time server 195.210.189.106 offset -249.015251 sec
Local time: Sun 2019-08-25 21:00:10 +03
Universal time: Sun 2019-08-25 18:00:10 UTC
RTC time: Sun 2019-08-25 18:00:10
Time zone: Europe/Minsk (+03, +0300)
NTP enabled: yes
NTP synchronized: yes
RTC in local TZ: no
DST active: n/a
Всё отлично, время синхронизировалось, системное совпадает с аппаратным. «Забирай», — обронил я и вернулся к своим делам.
«Что забирай? — возмутился коллега. — Время прежнее!»
Чем больше решаешь типовых задач тем больше зашоривается мышление и уже не думаешь, что сотая или тысячная ситуация будет другой, но не в этот раз.
# timedatectl
Local time: Sun 2019-08-25 21:09:15 +03
Universal time: Sun 2019-08-25 18:09:15 UTC
RTC time: Sun 2019-08-25 18:05:04
Time zone: Europe/Minsk (+03, +0300)
NTP enabled: yes
NTP synchronized: no
RTC in local TZ: no
DST active: n/a
Системное время снова неправильное.
Попробуем ещё раз:
# ntpdate 0.ru.pool.ntp.org && timedatectl && sleep 1 && timedatectl
25 Aug 21:07:37 ntpdate[30350]: step time server 89.175.20.7 offset -249.220828 sec
Local time: Sun 2019-08-25 21:07:37 +03
Universal time: Sun 2019-08-25 18:07:37 UTC
RTC time: Sun 2019-08-25 18:07:37
Time zone: Europe/Minsk (+03, +0300)
NTP enabled: yes
NTP synchronized: yes
RTC in local TZ: no
DST active: n/a
Local time: Sun 2019-08-25 21:11:46 +03
Universal time: Sun 2019-08-25 18:11:46 UTC
RTC time: Sun 2019-08-25 18:07:37
Time zone: Europe/Minsk (+03, +0300)
NTP enabled: yes
NTP synchronized: no
RTC in local TZ: no
DST active: n/a
Давайте по-другому:
# date -s "2019-08-25 21:10:30" && date && sleep 1 && timedatectl
Sun Aug 25 21:10:30 +03 2019
Sun Aug 25 21:10:30 +03 2019
Local time: Sun 2019-08-25 21:14:36 +03
Universal time: Sun 2019-08-25 18:14:36 UTC
RTC time: Sun 2019-08-25 18:10:30
Time zone: Europe/Minsk (+03, +0300)
NTP enabled: yes
NTP synchronized: no
RTC in local TZ: no
DST active: n/a
А вот так:
# hwclock --hctosys && timedatectl && sleep 1 && timedatectl
Local time: Sun 2019-08-25 21:11:31 +03
Universal time: Sun 2019-08-25 18:11:31 UTC
RTC time: Sun 2019-08-25 18:11:31
Time zone: Europe/Minsk (+03, +0300)
NTP enabled: yes
NTP synchronized: yes
RTC in local TZ: no
DST active: n/a
Local time: Sun 2019-08-25 21:15:36 +03
Universal time: Sun 2019-08-25 18:15:36 UTC
RTC time: Sun 2019-08-25 18:11:32
Time zone: Europe/Minsk (+03, +0300)
NTP enabled: yes
NTP synchronized: no
RTC in local TZ: no
DST active: n/a
Время устанавливается на долю секунды, и тут же начинает «спешить» вновь.
При этом в логах, на момент такой ручной смены, видим лишь отчёты системы, о том, что время изменилось, соответственно в правильную/неправильную стороны и изредка Resyncing от systemd-timesyncd.
Aug 25 21:18:51 wisi systemd[1]: Time has been changed
Aug 25 21:18:51 wisi systemd-timesyncd[29258]: System time changed. Resyncing.
Aug 25 21:18:51 wisi systemd[1187]: Time has been changed
Aug 25 21:18:51 wisi systemd[1]: Time has been changed
Aug 25 21:18:51 wisi systemd[1187]: Time has been changed
здесь
# ps afx | grep "[1]187"
1187 ? Ss 0:02 /lib/systemd/systemd --user
В этот момент уже нужно было искать причину, но мозг за 18 лет админства наработал статистику ошибок «времени» и по привычке снова обвиняет синхронизацию.
Отключаем её напрочь.
# timedatectl set-ntp off && systemctl stop systemd-timesyncd.service
# hwclock --hctosys && timedatectl && sleep 1 && timedatectl
Local time: Sun 2019-08-25 21:25:40 +03
Universal time: Sun 2019-08-25 18:25:40 UTC
RTC time: Sun 2019-08-25 18:25:40
Time zone: Europe/Minsk (+03, +0300)
NTP enabled: no
NTP synchronized: no
RTC in local TZ: no
DST active: n/a
Local time: Sun 2019-08-25 21:29:31 +03
Universal time: Sun 2019-08-25 18:29:31 UTC
RTC time: Sun 2019-08-25 18:25:41
Time zone: Europe/Minsk (+03, +0300)
NTP enabled: no
NTP synchronized: no
RTC in local TZ: no
DST active: n/a
и в логах
Aug 25 21:25:40 wisi systemd[1]: Time has been changed
Aug 25 21:25:40 wisi systemd[1187]: Time has been changed
Aug 25 21:29:30 wisi systemd[1]: Time has been changed
Aug 25 21:29:30 wisi systemd[1187]: Time has been changed
Resyncing пропал и в остальном логи девственно чисты.
Проверяем выводы tcpdump по 123-му порту на всех интерфейсах. Никаких запросов нет, но время всё также «убегает».
Ошибка вторая. Спешка
До конца рабочей недели остаётся час, а уходить на выходные с плёвой нерешенной задачей не хочется (не обращайте внимания на время в коде, статья писалась в последующие дни).
И тут вновь вместо того чтобы искать причину я начал пытаться придумать объяснение результата. Я говорю «придумать», потому что не смотря на то, какими бы не были логичными объяснения результата, это ошибочный подход решения проблемы.
Данный сервер является стримминговым и преобразовывает поток DVB-S2 в IP. В потоке DVB-S присутствуют метки времени, поэтому приемники, мультиплексоры, скремблеры и телевизоры часто используют их для синхронизации системных часов. Драйвера DVB-S плат вкомпилены в ядро, поэтому самый быстрый способ гарантированно убрать DVB-S2-поток — это отключить кабели идущие с «тарелок». Благо сервер за стенкой, посему так тому и быть.
Конечно, если бы в логах было то, что там должно быть, этого бы не произошло, но об этом, опять, же, в конце статьи.
Ну и раз мы уже удалили все спутниковые сигналы удалим и наземные — попутно выдергиваем все сетевые кабеля. Сервер становится отрезанным от внешнего мира и работает абсолютно автономно, но системные часы всё также спешат.
Рабочая неделя окончена, а сам вопрос даты/времени на нем не критичен, поэтому можно просто пойти домой, но тут я делаю новую промашку.
Ошибка третья. Советчики
Никогда! Никогда не задавайте вопросы на форумах и общеспециализированных (а-ля stackoverflow) сайтах, если ответ на него требует больше чем изучение выдачи первой страницы гугла и прочитки одной страницы man'а.
Вас пошлют обратно в google, почитать всё тот же man и популярно объяснят правила форума/сайта, но не дадут ответа.
Здесь есть как объективные факторы:
- никто кроме вас не может знать проблему также хорошо;
- никто не может провести тесты в таких же как у вас условиях
так и субъективные:
- вы можете не выдать всех вводных для решения задачи, потому что уже придумали «правильное» направление и излагаете суть вопроса упирая на него;
- старшина (модератор, старожил, админ) всегда прав, если старшина не прав… ну вы знаете...
Если при ответных комментариях вы остались в рамках цензурной лексики, значит у вас крепкие нервы.
Решение
Не нужно делить задачи на простые и сложные.
Перестаём полагаться на свой опыт, статистику, советчиков и начинаем не «объяснять» конечный результат, а последовательно искать причину.
Раз некто устанавливает время значит должен произойти соответствующий системный вызов.
Как в документации софта лучшие доки — это исходники, так в системном администрировании лучший помощник — это аудит, в нашем случае auditd.
# man syscalls | col | grep -F '(2)' | grep -vE '(:|;)' | grep -E '(time|date|clock)' | sed "s/(2).*//" | xargs -I SYSCALL echo "-S SYSCALL " | xargs echo
-S adjtimex -S clock_adjtime -S clock_getres -S clock_gettime -S clock_nanosleep -S clock_settime -S futimesat -S getitimer -S gettimeofday -S mq_timedreceive -S mq_timedsend -S rt_sigtimedwait -S s390_runtime_instr -S setitimer -S settimeofday -S stime -S time -S timer_create -S timer_delete -S timer_getoverrun -S timer_gettime -S timer_settime -S timerfd_create -S timerfd_gettime -S timerfd_settime -S times -S utime -S utimensat -S utimes
и отбросив s390_runtime_instr, stime, timerfd_create, которых auditctl не признал, изначально запустил аудит в виде:
auditctl -a exit,always -S adjtimex -S clock_adjtime -S clock_getres -S clock_nanosleep -S clock_settime -S futimesat -S getitimer -S gettimeofday -S mq_timedreceive -S mq_timedsend -S rt_sigtimedwait -S semtimedop -S setitimer -S settimeofday -S time -S timer_create -S timer_delete -S timer_getoverrun -S timer_gettime -S timer_settime -S timerfd_gettime -S timerfd_settime -S times -S utime -S utimensat -S utimesУбедившись, что в интересующих меня местах логов нет других syscalls кроме этих двух далее использовал только их.
Запускаем аудит системных вызовов clock_settime и settimeofday и пробуем сменить дату:
# auditctl -a exit,always -S clock_settime -S settimeofday && date -s "2019-08-22 12:10:00" && sleep 5 && auditctl -D
Пятисекундная задержка добавлена, чтобы наш «паразит» гарантированно откорректировал время.
Смотрим отчет:
# aureport -s -i
Syscall Report
=======================================
# date time syscall pid comm auid event
=======================================
Warning - freq is non-zero and incremental flushing not selected.
1. 08/22/2019 12:10:00 settimeofday 3088 chkcache_proces root 479630
2. 08/26/2019 09:37:06 clock_settime 1538 date root 479629
Здесь мы видим наш date и неизвестный нам chkcache_proces. Он оказался в отчете выше, так как aureport отсортировал вывод по дате при преобразовании из бинарного вида, а событие произошло в установленное нами время date -s «2019-08-22 12:10:00».
Кто же его породил?
# ausearch -sc settimeofday --comm "chkcache_proces"
----
time->Thu Aug 22 12:10:00 2019
type=PROCTITLE msg=audit(1566465000.000:479630): proctitle="/usr/local/bin/oscam"
type=SYSCALL msg=audit(1566465000.000:479630): arch=c000003e syscall=164 success=yes exit=0 a0=7fde0dfc6e60 a1=0 a2=136cf a3=713ba56 items=0 ppid=3081 pid=3088 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts20 ses=68149 comm="chkcache_proces" exe="/usr/local/bin/oscam" key=(null)
/usr/local/bin/oscam — наш паразит найден. Несмотря на его «зловредное» поведение отказаться от системы условного доступа нельзя, но всё же хотелось бы знать, oscam, WTF?
Ответ быстро найден в исходниках:
#if defined(CLOCKFIX)
if (tv.tv_sec > lasttime.tv_sec || (tv.tv_sec == lasttime.tv_sec && tv.tv_usec >= lasttime.tv_usec)) // check for time issues!
{
lasttime = tv; // register this valid time
}
else
{
tv = lasttime;
settimeofday(&tv, NULL); // set time back to last known valid time
//fprintf(stderr, "*** WARNING: BAD TIME AFFECTING WHOLE OSCAM ECM HANDLING, SYSTEMTIME SET TO LAST KNOWN VALID TIME **** \n");
}
Как же мило здесь смотрится закомментированная строчка warning'a…
Комментарии (32)
amarao
26.08.2019 13:38+4Спасибо за байки. Очень полезно. Насчёт SO...
Никогда! Никогда не задавайте вопросы на форумах и общеспециализированных (а-ля stackoverflow) сайтах, если ответ на него требует больше чем изучение выдачи первой страницы гугла и прочитка одной страницы man'а..
Иногда в ответ прилетает сакральное (теоретическое) знание или фундаментальный вопрос на который трудно ответить (и ответ на который содержит всё). А ещё сокращённое изложение проблемы для SO с minimal reproducable — отличный метод отладки. Другими словами, если ничерта не понятно, то описать что именно ничерта не понятно так, чтобы другие люди поняли что именно не понятно — это полезно.
akdes
26.08.2019 14:34именно так и решаются мои проблемы в основном, т.к. для написания вопроса, мало того, что необходимо «переписать» вопрос из головы на более понятный язык, в процессе чего сам начинаешь понимать проблему, так ещё постоянно, за место того, что бы запостить «кто-то насрал, как исправить?» — делаешь анализ проблемы и в моём случае, в 55% проблема была не том, и в 40% она решалась во время анализа или описания. Ну а 4% шли на отдых и смену обстановки — утро вечера мудренее и 1% когда проблема реально существовала и не решалась собственными усилиями.
Однако не редкость, что в проблемах 1% нужно действительно действовать по «Никогда! Никогда..!» Ибо в основном в проблемах такого характера никто не захочет лазить дальше посыла в гугл и мануалов.
mOlind
26.08.2019 14:58+1Rubber duck debugging. Пока рассказывал в чем проблема, сам понял из-за чего так происходит.
Delsian
26.08.2019 15:16+4В 90% случаев после написания вопроса на форуме в голове щелкает и ты через 5 минут понимаешь, где ошибка.
Но обязательно надо нажать кнопку «Отправить» — без нее эта магия не срабатывает!
ky0
26.08.2019 15:32+1А потом ответить самому себе и отметить как решение. Постойте-ка, да это же Тостер во плоти!
tangro
27.08.2019 10:12+2Не, потом надо написать «А, всё, разобрался сам» и закрыть без объяснения :)
river-fall
27.08.2019 13:08-1«Нашёл остроумное решение теоремы, но поля книги слишком маленькие для его изложения»
ThunderCat
26.08.2019 16:55Другими словами, если ничерта не понятно, то описать что именно ничерта не понятно так, чтобы другие люди поняли что именно не понятно — это полезно.
как куратор тега на тостере — готов подписаться под каждым словом, но не все обладают столь полезным скилом, из большинства приходится клещами тянуть что и как «не работает» (
Alexey2005
26.08.2019 16:21В Linux ситуация, когда какая-то сука раз за разом сбивает нужные настройки, встречается удивительно часто. Это касается любых настроек: DNS, маршрутизация, звук, cron, системное время и много всего прочего.
После очередной пары-тройки часов, проведённых за «перетряхиванием» системы в поисках виновного, начинаешь задаваться вопросом: а для разработчиков Linux'ового софта вообще существуют правила хорошего тона, или каждое приложение «думает», что кроме него на машине больше ничего не запускается?mayorovp
26.08.2019 16:49Это общая беда для любых ОС. В linux, на самом деле, всё куда лучше чем в альтернативах — потому что обычно всё-таки можно найти сбивальщика и отключить.
usheynet
28.08.2019 00:14Не для любых, как мне видится. В той же макоси/айоси за рамки особо не выйдешь, дизайн (архитектура) не позволяет. Винду тоже, вроде, причесывать начали в сторону большей строгости.
Murimonai
26.08.2019 16:57+1Если установленные приблуды работают не от рута — такой проблемы скорее всего не возникнет. Потому что почитать конфиг файл — максимум дозволенного, править или запускать — error: permission denied ?\_(?)_/?
lorc
26.08.2019 19:40Вообще правила хорошего тона есть. И мейнтейнеры дистрибутивов стараются за этим следить. Но как вы могли заметить, этот процесс запускался из /usr/local/bin. Что автоматически превращает проблему в локальную для конкретной машины. Да и вообще: софт, в исходниках которого есть закоментированный код — попахивает, скажем так.
vitaly_il1
27.08.2019 08:10ИМХО, это проблема последних 10 лет, когда появились всякие надстройки — networkd+NetworkManager+NetPlan, вместо systemV комбинация systemd+upstart и т.д.
mayorovp
27.08.2019 08:39Ну, если говорить о надстройках — то проблема всё-таки не в них, а в устаревшей документации.
У того же networkd есть свои конфиги, лежащие в /etc/systemd/network — но если знать только про /etc/network/interfaces (или вообще только ifconfig), то поведение системы сразу же становится очень загадочным.
vitaly_il1
27.08.2019 08:52Если бы старую систему заменили на новую, это еще полбеды. Проблема что все живет вместе, в разных комбинациях, и надо разбираться что и когда из этого зоопарка активно в каждой дистро.
Даже с десятком разных Юниксов двадцать лет назад было проще. Или моложе был :-)
mikeus
26.08.2019 19:18Не всяк админ полезет копаться с аудитом системных вызовов ядра — поучительно. Теперь же предусмотрительный, он должен пытаться настроить время на сервере только предварительно отключив всю периферию, все интерфейсы, и заглушив все сервисы в single user mode. Или для пущей верности — загрузившись в emergency mode и перемонтировав потом корень в rw.
Не понятно только, как дальше будет жить автоматическая подстройка времени из systemd-timesyncd или chrony с такими соседствующими пакостниками.
Kwisatz
26.08.2019 19:52И тут вновь вместо того чтобы искать причину я начал пытаться придумать объяснение результата.
А у меня ровно наоборот. Я теперь даже в квиз играть не способен. Ибо каждый раз, когда я пытался обращаться с некой системой или библиотекой так, как оно должно быть или кажется, что должно, возникали очень большие проблемы.
Никогда не задавайте вопросы на форумах и общеспециализированных (а-ля stackoverflow) сайтах
С определенного момента это становиться истиной почти для всего. Если проблема еще не описана есть очевидный для всех нюанс (дико бесит) либо на планете 2.5 человека, разбирающихся в предмете.
puyol_dev2
26.08.2019 21:21-4Ну что тут сказать… говнософт. Меня удивляют люди, которые чуть ли не обожествляют Линукс. Вы посмотрите сначала, кто пишет и как пишет в тех же исходниках. Нередко это просто тихий ужас, настоящий код made in India
realimba
26.08.2019 23:02-4по крайней мере у него есть шанс потихоньку стать нормальным, в отличии от гвн блобов от m$ и друзей..
citius
27.08.2019 12:07+1Причем тут вообще линукс?
Есть гарантия, что этот же самый продукт, написанный этим же самым автором под винду вел бы себя иначе?
Опыт общения с крутыми и дорогими софтверными продуктами вроде Cisco Unified Communications показывает, что там внутри зачастую гораздо более жуткий бардак и нагромождение дичайших костылей.puyol_dev2
27.08.2019 13:55Меня удивляет не то, что в коммерческом софте полно багов. Меня удивляет фанатичная любовь к софту, в котором этих багов не меньше
eumorozov
28.08.2019 10:18Я люблю, потому что так же, как у автора в статье, всегда есть возможность докопаться в исходниках до первопричины и исправить. Пускай это требуется лишь раз в 10 лет, но все равно. На самом деле, чаще. Я хоть и не имею времени серьезно контрибьютить в open source, но на самом деле за год создаю как минимум пару пулл-реквестов на github к популярным проектам.
Nokse
26.08.2019 21:26simpleadmin спасибо за то, что поделились интересной информацией. Добавил статью в закладки.
<оффтопик> вот кто-бы мне помог разобраться с двумя интересными вещами, с которыми я так и не управился…
1. Не синхронизируется время в Вин 10 (LTSB). Ни в какую. Перекурил уже все возможные мануалы (которые либо бесполезны вообще, либо переписаны друг у друга и сводятся к одному), но время по прежнему не хочет синхронизироваться…
2. На этой самой винде периодически самопроизвольно разлогинивается Скайп… И при каждом запуске просит залогиниться… На линуксе всё ок, на телефоне всё ок, и только на винде непонятная ерунда с недержанием сессии. Ничего внятного вообще не нашел…
</оффтопик>Kwisatz
26.08.2019 23:25+1Первое знакомо, бился сам с этим делом очень долго. Не смог победить вообще никак. Отрезал к чертям синхронизацию, поменял батарейку на маме и выставил часики.
darthslider
27.08.2019 10:20«Не хочет синхронизироваться» это что значит? Ошибка какая-то есть?
Попробуйте перерегистрировать сервис:
Net Stop W32time
W32tm.exe /unregister
W32tm.exe /register
Net Start W32time
Miiihus
27.08.2019 10:11Под виндой как-то мучился с похожей проблемой. У DC постоянно время сбивалось чуть ли не на полчаса, несмотря на всю синхронизацию. А ларчик просто открывался: DC был виртуалкой, а на хосте время было сбито.
questor
Статья интересная, но такое впечатление, что автору всё-таки надо было уйти на выходные и он не дописал статью оборвав на самом интересном ме...
DDoSInsurance
Вероятно, Вы не поняли, сарказма последней фразы соотнесенной с закомментированным выводом в stderr, о чем дважды было упомянуто в статье.
Если бы не этот двойной слеш этой истории не было бы вообще.