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

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

Источник: habr.com