🥇タスクが単純であればあるほど、間違いを犯すことが多くなります

この些細なタスクは、ある金曜日の午後に発生し、2 ～ 3 分かかるはずでした。一般的には、いつものように。

同僚からサーバー上のスクリプトを修正するように頼まれました。私はそれを実行し、彼にそれを渡し、うっかり「時間は5分早いです」と言いました。サーバーに同期自体を処理させます。 XNUMX分、XNUMX時間経っても、彼はまだ息を吹き返し、静かに悪態をつき続けた。

"バカ！ — サーバーコンソールに切り替えながら、私は思いました — わかりました、あと XNUMX、XNUMX 分休憩しましょう。」

見てみましょう 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

すべて問題なく、時刻は同期されており、システム時刻はハードウェア時刻と一致しています。「どうぞ」と私は言って、仕事に戻りました。

"何を取ります？ - 同僚は憤慨していました。「同じ時間だよ！」

典型的な問題を解決すればするほど、思考が混乱し、XNUMX 番目や XNUMX 番目の状況が変わるとは考えなくなりますが、今回はそうではありません。

# 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

再同期 消えた場合、ログは元の状態のままです。

結論を確認する tcpdump すべてのインターフェイスのポート 123 で。リクエストはありませんが、時間は過ぎています。

エラーXNUMX。急ぐ

週の終わりまであと XNUMX 時間ありますが、些細な未解決の問題を抱えたまま週末に出発したくありません (コード内の時間には注意しないでください。この記事は数日後に書かれています) ）。
そしてここでも、理由を探すのではなく、結果の説明を考え出し始めました。私が「発明する」と言ったのは、結果の説明がどれほど論理的であっても、それは問題を解決するアプローチとしては欠陥があるからです。

このサーバーはストリーミングサーバーであり、DVB-S2 ストリームを IP に変換します。 DVB-S ストリームにはタイムスタンプが含まれているため、受信機、マルチプレクサー、スクランブラー、テレビはシステムクロックを同期するためにタイムスタンプを使用することがよくあります。 DVB-S ボードドライバーはカーネルに組み込まれているため、DVB-S2 ストリームを確実に削除する最も速い方法は、「プレート」からのケーブルを外すことです。幸いなことに、サーバーは壁の後ろにあるので、大丈夫です。

もちろん、そこにあるべきものがログに含まれていれば、このようなことは起こらなかったはずですが、それについては、記事の最後でもう一度説明します。

さて、すでにすべての衛星信号を削除したので、地上波の信号も削除します。同時に、すべてのネットワークケーブルも引き出します。サーバーは外部の世界から切り離され、完全に自律的に動作しますが、システムクロックは依然として早い状態です。

週の勤務時間は終了しており、日時の問題自体は重要ではないので、そのまま帰宅しても構いませんが、ここで私は新たな間違いを犯してしまいました。

エラーXNUMX。アドバイザー

一度もない！ Google の最初のページを調べたりマニュアルページを XNUMX つ読んだりする以上に答えが必要な場合は、フォーラムや一般的な専門 (スタックオーバーフローのような) サイトで質問しないでください。

彼らはあなたを Google に送り返し、同じ人物の文章を読み、フォーラム/サイトのルールを一般的に説明しますが、答えは与えません。

以下に客観的な要因をいくつか示します。

あなた以外の誰もその問題を知ることはできません。
誰もあなたと同じ条件でテストを実施することはできません

そして主観的:

あなたはすでに「正しい」方向性を思いつき、そこに焦点を当てて問題の本質を提示しているため、問題を解決するためのすべての情報を提供することはできません。
職長 (モデレーター、ベテラン、管理者) は常に正しく、もし職長が間違っていても... そうですね...

コメントに返信するときに、検閲された語彙の範囲内に留まっている場合、あなたは強い神経を持っています。

ソリューション

タスクを単純なものと複雑なものに分ける必要はありません。

私たちは自分の経験、統計、アドバイザーに頼ることをやめ、最終結果を「説明」するのではなく、一貫してその理由を探し始めます。

誰かが時間を設定するので、それに対応するシステムコールが発生する必要があります。

ソフトウェアのドキュメントにおいて最良のドキュメントがソースであるのと同様に、システム管理においても最良のアシスタントは監査です。この場合、監査.

一瞬の疑問mana を調べましたが、Linux で時刻を設定することしかできないかどうかは完全にはわかりませんでした。 クロック設定時間 и 設定時刻したがって、最初のテストでは、すべての「適切な」呼び出しを選択しました。

# 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どれ 監査ctl それを認識せず、最初は次の形式で監査を開始しました。

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

関心のあるログの場所に他のログがないことを確認した後、 システムコール この XNUMX つ以外には、さらにこれらのみを使用しました。

システムコール監査の実行 クロック設定時間 и 設定時刻 そして日付を変更してみます。

# auditctl -a exit,always -S clock_settime -S settimeofday && date -s "2019-08-22 12:10:00" && sleep 5 && auditctl -D

「寄生虫」が時刻を修正することが保証されるように、XNUMX 秒の遅延が追加されます。

レポートを見ます：

# 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_processes。 aureport はバイナリから変換するときに出力を日付でソートし、設定した時間にイベントが発生したため、最終的に上記のレポートになりました。 日付 -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 - 私たちの寄生虫が見つかりました。たとえ「悪意のある」行為であっても、条件付き受信システムを拒否することは不可能ですが、それでも知りたいです オスカム、何ということですか？

答えはすぐに見つかりますソースコード:

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

ここはなんて可愛いんだろう コメントアウトされた ライン警告...

出所： habr.com

タスクが単純であればあるほど、間違いを犯すことが多くなる

最初の間違い。自信

エラーXNUMX。急ぐ

エラーXNUMX。アドバイザー

ソリューション

コメントを追加します返信をキャンセル

タスクが単純であればあるほど、間違いを犯すことが多くなる

最初の間違い。 自信

エラーXNUMX。 急ぐ

エラーXNUMX。 アドバイザー

ソリューション

コメントを追加します 返信をキャンセル

最初の間違い。自信

エラーXNUMX。急ぐ

エラーXNUMX。アドバイザー

コメントを追加します返信をキャンセル