كلما كانت المهمة أبسط، كلما ارتكبت أخطاء أكثر

كلما كانت المهمة أبسط، كلما ارتكبت أخطاء أكثر

نشأت هذه المهمة التافهة بعد ظهر أحد أيام الجمعة، وكان من المفترض أن تستغرق 2-3 دقائق من الوقت. بشكل عام، كما هو الحال دائما.

طلب مني أحد الزملاء إصلاح البرنامج النصي على خادمه. لقد فعلت ذلك، وسلمته له وأسقطته عن غير قصد: "الوقت سريع 5 دقائق". دع الخادم يتعامل مع المزامنة بنفسه. مرت نصف ساعة، ساعة، وما زال ينفخ ويلعن بهدوء.

"غبي! - فكرت، عند التبديل إلى وحدة تحكم الخادم - حسنًا، سأأخذ قسطًا من الراحة لبضع دقائق إضافية.

نحن ننظر نتب، رديت، سدودات غير مثبت مرات معطل ولا يعمل.

# 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

يتم ضبط الوقت على جزء من الثانية، ويبدأ على الفور في "الاندفاع" مرة أخرى.

في الوقت نفسه، في السجلات، في وقت هذا التغيير اليدوي، نرى فقط تقارير النظام التي تفيد بأن الوقت قد تغير، على التوالي، في الاتجاه الصحيح/الخاطئ وفي بعض الأحيان إعادة المزامنة من 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

إعادة المزامنة اختفت وإلا فإن السجلات نظيفة.

التحقق من الاستنتاجات com.tcpdump على المنفذ 123 على كافة الواجهات. لا توجد طلبات، ولكن الوقت لا يزال ينفذ.

الخطأ الثاني. يسرع

هناك ساعة متبقية حتى نهاية أسبوع العمل، ولا أريد المغادرة لعطلة نهاية الأسبوع مع مشكلة تافهة لم يتم حلها (لا تنتبه للوقت في الكود، تمت كتابة المقالة في الأيام التالية) ).
وهنا مرة أخرى، بدلاً من البحث عن السبب، بدأت أحاول التوصل إلى تفسير للنتيجة. أقول "اخترع" لأنه بغض النظر عن مدى منطقية تفسير النتيجة، فهو نهج خاطئ لحل المشكلة.

هذا الخادم هو خادم دفق ويقوم بتحويل دفق DVB-S2 إلى IP. يحتوي دفق DVB-S على طوابع زمنية، لذا غالبًا ما تستخدمها أجهزة الاستقبال ومضاعفات الإرسال وأجهزة التشويش وأجهزة التلفزيون لمزامنة ساعة النظام. برامج تشغيل لوحة DVB-S مدمجة في النواة، لذا فإن أسرع طريقة لضمان إزالة دفق DVB-S2 هي فصل الكابلات القادمة من "اللوحات". لحسن الحظ، الخادم خلف الجدار، فليكن.

بالطبع، إذا كانت السجلات تحتوي على ما يجب أن يكون هناك، فلن يحدث هذا، ولكن المزيد عن ذلك، مرة أخرى، في نهاية المقال.

حسنًا، نظرًا لأننا قمنا بالفعل بإزالة جميع إشارات الأقمار الصناعية، فسوف نقوم أيضًا بإزالة الإشارات الأرضية - وفي نفس الوقت نقوم بسحب جميع كابلات الشبكة. يصبح الخادم معزولًا عن العالم الخارجي ويعمل بشكل مستقل تمامًا، لكن ساعة النظام لا تزال في عجلة من أمرها.

لقد انتهى أسبوع العمل، ومشكلة التاريخ/الوقت في حد ذاتها ليست حرجة، لذا يمكنك العودة إلى المنزل فحسب، ولكن هنا ارتكبت خطأً جديدًا.

الخطأ الثالث. المستشارين

أبداً! لا تطرح أبدًا أسئلة في المنتديات والمواقع العامة المتخصصة (على غرار Stackoverflow) إذا كانت الإجابة عليها تتطلب أكثر من مجرد دراسة الصفحة الأولى من Google وقراءة صفحة رئيسية واحدة.

سوف يعيدونك إلى Google، ويقرأون نفس الرجل ويشرحون قواعد المنتدى/الموقع بشكل عام، لكنهم لن يعطوك إجابة.

فيما يلي بعض العوامل الموضوعية:

  • ولا أحد غيرك يمكنه معرفة المشكلة أيضًا؛
  • لا يمكن لأحد إجراء الاختبارات في ظل نفس ظروفك

وذاتية:

  • قد لا تقدم كل المدخلات لحل المشكلة، لأنك قد توصلت بالفعل إلى الاتجاه "الصحيح" وتقدم جوهر المشكلة مع التركيز عليه؛
  • رئيس العمال (المشرف، القديم، المشرف) دائمًا على حق، إذا كان رئيس العمال مخطئًا... حسنًا، كما تعلم...

إذا كنت عند الرد على التعليقات بقيت ضمن حدود المفردات الخاضعة للرقابة، فهذا يعني أن أعصابك قوية.

حل

ليست هناك حاجة لتقسيم المهام إلى بسيطة ومعقدة.

نتوقف عن الاعتماد على خبرتنا وإحصائياتنا ومستشارينا ونبدأ بعدم "شرح" النتيجة النهائية، بل نبحث باستمرار عن السبب.

نظرًا لأن شخصًا ما يقوم بتعيين الوقت، فيجب إجراء استدعاء النظام المقابل.

كما هو الحال في توثيق البرامج، فإن أفضل المستندات هي المصادر، لذلك فإن أفضل مساعد في إدارة النظام هو التدقيق، في حالتنا Auditd.

لحظة شكلقد قمت بمراجعة Mana، لكنني لم أكن متأكدًا تمامًا من أنه لا يمكن ضبط الوقت في Linux إلا Clock_settime и يوم التسوية، لذلك اخترت في الاختبار الأول جميع المكالمات "المناسبة":

# 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، أيّ com.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 и يوم التسوية وحاول تغيير التاريخ:

# 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_processes. انتهى الأمر بالتقرير أعلاه لأن تقرير aureport قام بفرز الإخراج حسب التاريخ عند التحويل من الملف الثنائي، وقد وقع الحدث في الوقت الذي حددناه التاريخ "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 - تم العثور على الطفيلي لدينا. على الرغم من سلوكه "الخبيث"، فمن المستحيل رفض نظام الوصول المشروط، لكنني ما زلت أرغب في معرفة ذلك com.oscam، ماهذا الهراء؟

تم العثور على الجواب بسرعة في رموز المصدر:

#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");
}

كم يبدو لطيفا هنا علق بها خط تحذير...

المصدر: www.habr.com

إضافة تعليق