Чем проще задача, тем чаще я ошибаюсь26.08.2019 13:48

image
Эта тривиальная задача возникла в один из пятничных дней и должна была занять 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.

Минутка сомнения
Я пробежался по манам, но не был до конца уверен, что время в Linux может устанавливаться только clock_settime и settimeofday, поэтому для первого теста выбрал все «подходящие» вызовы:

# 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…

© Habrahabr.ru