Ця тривіальна задача виникла в один із п'ятничних днів і мала зайняти 2-3 хвилини часу. Загалом, як завжди.
Колега попросив виправити скрипт у нього на сервері. Зробив, здав йому й упустив ненароком: «Час поспішає на 5 хвилин». Сервер його, хай сам і розбирається із синхронізацією. Півгодини, година минула, а він все пихкає і тихо матюкається.
«Безболота! — подумав я, переключаючись у консоль сервера — ну ладно відірвуся ще на кілька хвилин.
Дивимося, ntp, rdate, sdwdate не встановлені, синхронізація часу вимкнено та не запущено.
# 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 зник і в іншому логи незаймані.
Перевіряємо висновки TCPDOMP по 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Переконавшись, що в місцях лігів, що цікавлять мене, немає інших системні виклики крім цих двох далі використовував лише їх.
Запускаємо аудит системних викликів 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
Тут ми бачимо наш дата і невідомий нам 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