カテゴリー: OSについて
投稿者: shinichi
ntp_config.cのソースファイルを見ていたら、"maxpoll: provided value (%d) is above maximum (%d)"というメッセージがあった。

maxpollの最大値は16とされているので、ntp.conf内で"maxpoll 20"と設定をするとエラーメッセージが出力されると思ってテストした。
開発1号機:ntp-4.1.2-4.EL3.1
開発2号機:ntp-4.2.0.a.20040617-4.EL4.1

試みその一

試してみました。"maxpoll 20"で。

結果(1号機):
ntpd.log
"
15 Sep 12:57:51 ntpd[31704]: running as uid(38)/gid(38) euid(38)/egid(38).
15 Sep 12:57:51 ntpd[31704]: system event 'event_restart' (0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
15 Sep 12:57:53 ntpd[31704]: peer 123.456.789.098 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
15 Sep 12:58:06 ntpd[31704]: peer LOCAL(0) event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
15 Sep 12:59:00 ntpd[31704]: system event 'event_peer/strat_chg' (0x04) status 'sync_alarm, sync_ntp, 2 events, event_restart' (0xc621)
15 Sep 12:59:00 ntpd[31704]: kernel time discipline status change 41
15 Sep 12:59:00 ntpd[31704]: system event 'event_sync_chg' (0x03) status 'leap_none, sync_ntp, 3 events, event_peer/strat_chg' (0x634)
15 Sep 12:59:00 ntpd[31704]: system event 'event_peer/strat_chg' (0x04) status 'leap_none, sync_ntp, 4 events, event_sync_chg' (0x643)
15 Sep 12:59:34 ntpd[31704]: kernel time discipline status change 1
15 Sep 13:57:50 ntpd[31704]: offset 0.000048 sec freq 7.999 ppm error 0.000052 poll 4
15 Sep 14:57:51 ntpd[31704]: offset -0.000238 sec freq 9.235 ppm error 0.000054 poll 5
15 Sep 15:57:51 ntpd[31704]: offset 0.000064 sec freq 8.666 ppm error 0.000020 poll 6
15 Sep 16:57:51 ntpd[31704]: offset -0.000692 sec freq 8.988 ppm error 0.002022 poll 7
15 Sep 17:57:51 ntpd[31704]: offset -0.000660 sec freq 8.863 ppm error 0.000429 poll 10
15 Sep 18:57:51 ntpd[31704]: offset -0.000444 sec freq 8.859 ppm error 0.000740 poll 11
15 Sep 19:36:13 ntpd[31704]: kernel time discipline status change 9
15 Sep 19:57:51 ntpd[31704]: offset -0.008352 sec freq 8.179 ppm error 0.003542 poll 11
15 Sep 20:57:51 ntpd[31704]: offset 0.002172 sec freq 8.547 ppm error 0.004831 poll 12
15 Sep 21:57:51 ntpd[31704]: offset 0.000417 sec freq 8.598 ppm error 0.004275 poll 12
15 Sep 22:57:51 ntpd[31704]: offset 0.000660 sec freq 8.638 ppm error 0.003704 poll 12
15 Sep 23:57:51 ntpd[31704]: offset -0.000731 sec freq 8.594 ppm error 0.003282 poll 13
16 Sep 00:57:51 ntpd[31704]: offset -0.000750 sec freq 8.548 ppm error 0.002843 poll 13
16 Sep 01:57:51 ntpd[31704]: offset -0.000750 sec freq 8.548 ppm error 0.002843 poll 13
16 Sep 02:57:51 ntpd[31704]: offset -0.000750 sec freq 8.548 ppm error 0.002843 poll 13
16 Sep 03:57:51 ntpd[31704]: offset -0.008941 sec freq 8.275 ppm error 0.004778 poll 13
16 Sep 04:57:51 ntpd[31704]: offset -0.008941 sec freq 8.275 ppm error 0.004778 poll 13
16 Sep 05:57:51 ntpd[31704]: offset 0.004730 sec freq 8.419 ppm error 0.007990 poll 14
16 Sep 06:57:51 ntpd[31704]: offset 0.004730 sec freq 8.419 ppm error 0.007990 poll 14
16 Sep 07:57:51 ntpd[31704]: offset -0.000711 sec freq 8.397 ppm error 0.007436 poll 14
16 Sep 08:57:51 ntpd[31704]: offset -0.000711 sec freq 8.397 ppm error 0.007436 poll 14
16 Sep 09:57:51 ntpd[31704]: offset -0.000711 sec freq 8.397 ppm error 0.007436 poll 14
16 Sep 10:57:51 ntpd[31704]: offset -0.000711 sec freq 8.397 ppm error 0.007436 poll 14
16 Sep 11:57:51 ntpd[31704]: offset -0.000711 sec freq 8.397 ppm error 0.007436 poll 14
16 Sep 12:57:51 ntpd[31704]: offset -0.005281 sec freq 8.317 ppm error 0.006833 poll 14
16 Sep 13:57:51 ntpd[31704]: offset -0.005281 sec freq 8.317 ppm error 0.006833 poll 14
16 Sep 14:57:51 ntpd[31704]: offset -0.005281 sec freq 8.317 ppm error 0.006833 poll 14
16 Sep 15:57:51 ntpd[31704]: offset -0.005281 sec freq 8.317 ppm error 0.006833 poll 14
16 Sep 16:57:51 ntpd[31704]: offset 0.011501 sec freq 8.492 ppm error 0.010268 poll 15
16 Sep 17:57:51 ntpd[31704]: offset 0.011501 sec freq 8.492 ppm error 0.010268 poll 15

~中略~

17 Sep 13:57:52 ntpd[31704]: offset -0.001231 sec freq 8.443 ppm error 0.009870 poll 15
17 Sep 14:57:52 ntpd[31704]: offset -0.001231 sec freq 8.443 ppm error 0.009870 poll 15
17 Sep 15:57:52 ntpd[31704]: offset -0.004637 sec freq 8.407 ppm error 0.008715 poll 16
17 Sep 16:57:52 ntpd[31704]: offset -0.004637 sec freq 8.407 ppm error 0.008715 poll 16

~中略~

18 Sep 16:57:53 ntpd[31704]: offset -0.001362 sec freq 8.397 ppm error 0.007723 poll 16
18 Sep 17:57:53 ntpd[31704]: offset -0.001362 sec freq 8.397 ppm error 0.007723 poll 16
18 Sep 18:57:53 ntpd[31704]: offset 0.000106 sec freq 8.397 ppm error 0.006729 poll 17
18 Sep 19:57:53 ntpd[31704]: offset 0.000106 sec freq 8.397 ppm error 0.006729 poll 17

~中略~

19 Sep 10:57:53 ntpd[31704]: offset 0.000106 sec freq 8.397 ppm error 0.006729 poll 17
19 Sep 11:57:53 ntpd[31704]: offset 0.000106 sec freq 8.397 ppm error 0.006729 poll 17
19 Sep 12:57:53 ntpd[31704]: offset -0.002818 sec freq 8.386 ppm error 0.006008 poll 16
19 Sep 13:57:53 ntpd[31704]: offset -0.002818 sec freq 8.386 ppm error 0.006008 poll 16

~中略~

21 Sep 17:57:55 ntpd[31704]: offset 0.004329 sec freq 8.395 ppm error 0.006312 poll 16
21 Sep 18:57:55 ntpd[31704]: offset 0.004329 sec freq 8.395 ppm error 0.006312 poll 16
21 Sep 19:57:55 ntpd[31704]: offset 0.000772 sec freq 8.398 ppm error 0.005748 poll 17
21 Sep 20:57:55 ntpd[31704]: offset 0.000772 sec freq 8.398 ppm error 0.005748 poll 17

~中略~

22 Sep 11:57:56 ntpd[31704]: offset 0.000772 sec freq 8.398 ppm error 0.005748 poll 17
22 Sep 12:57:56 ntpd[31704]: offset 0.000772 sec freq 8.398 ppm error 0.005748 poll 17
22 Sep 13:57:56 ntpd[31704]: offset -0.004090 sec freq 8.382 ppm error 0.005540 poll 16
22 Sep 14:57:56 ntpd[31704]: offset -0.004090 sec freq 8.382 ppm error 0.005540 poll 16

~中略~

23 Sep 21:57:57 ntpd[31704]: offset -0.004090 sec freq 8.382 ppm error 0.005540 poll 16
23 Sep 22:57:57 ntpd[31704]: offset -0.004090 sec freq 8.382 ppm error 0.005540 poll 16
23 Sep 23:33:31 ntpd[31704]: kernel time discipline status change 1
23 Sep 23:57:57 ntpd[31704]: offset 0.000000 sec freq 8.382 ppm error 0.000203 poll 6
24 Sep 00:57:57 ntpd[31704]: offset 0.000000 sec freq 8.382 ppm error 0.000005 poll 6
24 Sep 01:57:57 ntpd[31704]: offset 0.000000 sec freq 8.382 ppm error 0.000005 poll 6
24 Sep 02:57:57 ntpd[31704]: offset 0.000624 sec freq 7.146 ppm error 0.000218 poll 9
24 Sep 03:57:57 ntpd[31704]: offset 0.003131 sec freq 7.178 ppm error 0.000655 poll 10
24 Sep 04:57:57 ntpd[31704]: offset 0.004188 sec freq 7.312 ppm error 0.000528 poll 8
24 Sep 05:57:57 ntpd[31704]: offset 0.000421 sec freq 8.024 ppm error 0.000102 poll 9
24 Sep 06:57:57 ntpd[31704]: offset 0.000054 sec freq 8.189 ppm error 0.000016 poll 6
24 Sep 07:57:57 ntpd[31704]: offset 0.000132 sec freq 8.311 ppm error 0.000022 poll 7
24 Sep 08:57:57 ntpd[31704]: offset -0.000058 sec freq 8.335 ppm error 0.001162 poll 9
"

ntpq -p

remote refid st t when poll reach delay offset jitter
==============================================================================
*123.456.789.098 123.456.789.1 2 u 429 512 377 0.135 -0.022 0.028
LOCAL(0) LOCAL(0) 11 l 41 64 377 0.000 0.000 0.004


なぜ途中でpolling 16から6に戻ってしまったのかはこのログからだと不明です。"kernel time discipline status change 1"はntpデーモンを起動したときにも出てくるメッセージなので、もしかしたら途中でデーモンが落ちた??謎です。

そもそも期待していたエラーが出なかったのが残念でした。

結果(2号機):
ntpd.log
"
15 Sep 12:57:23 ntpd[20341]: system event 'event_restart' (0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
15 Sep 12:57:24 ntpd[20341]: peer 123.456.789.098 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
15 Sep 12:57:25 ntpd[20341]: peer LOCAL(0) event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
15 Sep 13:00:09 ntpd[20341]: system event 'event_peer/strat_chg' (0x04) status 'sync_alarm, sync_ntp, 2 events, event_restart' (0xc621)
15 Sep 13:00:09 ntpd[20341]: synchronized to 123.456.789.098, stratum 2
15 Sep 13:00:09 ntpd[20341]: kernel time sync disabled 0041
15 Sep 13:00:09 ntpd[20341]: system event 'event_sync_chg' (0x03) status 'leap_none, sync_ntp, 3 events, event_peer/strat_chg' (0x634)
15 Sep 13:00:09 ntpd[20341]: system event 'event_peer/strat_chg' (0x04) status 'leap_none, sync_ntp, 4 events, event_sync_chg' (0x643)
15 Sep 13:01:14 ntpd[20341]: kernel time sync enabled 0001
15 Sep 13:57:26 ntpd[20341]: offset 0.000076 sec freq -10.358 ppm error 0.000500 poll 7
15 Sep 14:57:29 ntpd[20341]: offset 0.001830 sec freq -10.103 ppm error 0.000667 poll 8
15 Sep 15:57:32 ntpd[20341]: offset 0.000819 sec freq -10.060 ppm error 0.000518 poll 9
15 Sep 16:57:35 ntpd[20341]: offset 0.003252 sec freq -10.038 ppm error 0.001683 poll 10
15 Sep 17:16:59 ntpd[20341]: kernel time sync enabled 0009
15 Sep 17:57:38 ntpd[20341]: offset 0.000493 sec freq -9.740 ppm error 0.000456 poll 11
15 Sep 18:57:41 ntpd[20341]: offset 0.001259 sec freq -9.586 ppm error 0.000766 poll 12
15 Sep 19:57:44 ntpd[20341]: offset -0.007421 sec freq -10.491 ppm error 0.008680 poll 12
15 Sep 20:57:48 ntpd[20341]: offset 0.001426 sec freq -10.404 ppm error 0.008847 poll 12
15 Sep 21:57:51 ntpd[20341]: offset 0.005827 sec freq -10.049 ppm error 0.004401 poll 13
15 Sep 22:57:54 ntpd[20341]: offset 0.000494 sec freq -10.019 ppm error 0.005333 poll 13
15 Sep 23:57:57 ntpd[20341]: offset 0.000494 sec freq -10.019 ppm error 0.005333 poll 13
16 Sep 00:58:00 ntpd[20341]: offset 0.000733 sec freq -9.997 ppm error 0.000239 poll 13
16 Sep 01:58:03 ntpd[20341]: offset 0.000733 sec freq -9.997 ppm error 0.000239 poll 13
16 Sep 02:58:06 ntpd[20341]: offset -0.007565 sec freq -10.227 ppm error 0.008298 poll 14
16 Sep 03:58:09 ntpd[20341]: offset -0.007565 sec freq -10.227 ppm error 0.008298 poll 14
16 Sep 04:58:12 ntpd[20341]: offset -0.007565 sec freq -10.227 ppm error 0.008298 poll 14
16 Sep 05:58:15 ntpd[20341]: offset 0.006732 sec freq -10.022 ppm error 0.014298 poll 14
16 Sep 06:58:18 ntpd[20341]: offset 0.006732 sec freq -10.022 ppm error 0.014298 poll 14
16 Sep 07:58:21 ntpd[20341]: offset 0.006732 sec freq -10.022 ppm error 0.014298 poll 14
16 Sep 08:58:24 ntpd[20341]: offset 0.006732 sec freq -10.022 ppm error 0.014298 poll 14
16 Sep 09:58:27 ntpd[20341]: offset 0.001910 sec freq -9.993 ppm error 0.004822 poll 14
16 Sep 10:58:30 ntpd[20341]: offset 0.001910 sec freq -9.993 ppm error 0.004822 poll 14
16 Sep 11:58:33 ntpd[20341]: offset 0.001910 sec freq -9.993 ppm error 0.004822 poll 14
16 Sep 12:58:36 ntpd[20341]: offset 0.001910 sec freq -9.993 ppm error 0.004822 poll 14
16 Sep 13:58:39 ntpd[20341]: offset 0.001910 sec freq -9.993 ppm error 0.004822 poll 14
16 Sep 14:58:42 ntpd[20341]: offset -0.000757 sec freq -10.004 ppm error 0.002667 poll 15
16 Sep 15:58:45 ntpd[20341]: offset -0.000757 sec freq -10.004 ppm error 0.002667 poll 15

~中略~

17 Sep 11:59:45 ntpd[20341]: offset 0.029060 sec freq -9.779 ppm error 0.028832 poll 15
17 Sep 12:59:48 ntpd[20341]: offset 0.029060 sec freq -9.779 ppm error 0.028832 poll 15
17 Sep 13:59:52 ntpd[20341]: offset 0.019983 sec freq -9.627 ppm error 0.009077 poll 16
17 Sep 14:59:55 ntpd[20341]: offset 0.019983 sec freq -9.627 ppm error 0.009077 poll 16

~中略~

18 Sep 15:01:07 ntpd[20341]: offset 0.021678 sec freq -9.462 ppm error 0.001695 poll 16
18 Sep 16:01:10 ntpd[20341]: offset 0.021678 sec freq -9.462 ppm error 0.001695 poll 16
18 Sep 17:01:13 ntpd[20341]: offset 0.001315 sec freq -9.457 ppm error 0.020363 poll 17
18 Sep 18:01:16 ntpd[20341]: offset 0.001315 sec freq -9.457 ppm error 0.020363 poll 17

~中略~

24 Sep 08:08:02 ntpd[20341]: offset 0.096578 sec freq -9.175 ppm error 0.051412 poll 17
24 Sep 09:08:05 ntpd[20341]: offset 0.096578 sec freq -9.175 ppm error 0.051412 poll 17
"

ntpq -p

remote refid st t when poll reach delay offset jitter
==============================================================================
*123.456.789.098 123.456.789.1 2 u 9h 36h 377 1.188 96.578 51.412
LOCAL(0) LOCAL(0) 10 l 64 64 377 0.000 0.000 0.004


1号機とは違い、こちらはずっと安定してpolling 17となっています。polling 16から17になるまでに丸一日。polling 17になってからすでに五日半経っているのにまだ18にならない。
でも、36時間に一度の時刻調整でも数十ミリ秒のずれなんだからなかなかすごいと思う(開発サーバーで今回の実験中ほとんど無負荷だったのも影響しているだろうが)。

こちらのサーバーでも期待していたエラーは出力されませんでした。何かテストの仕方が間違っているのかも・・・


試みその二

ついでなので、maxpollとminpollの値が逆になるようにも設定してみました。"minpoll 14 maxpoll 10"で。
こちらは結果が出るのがとても早かったです。

結果(開発1号機):
ntpd.log
"
14 Sep 13:27:34 ntpd[16798]: running as uid(38)/gid(38) euid(38)/egid(38).
14 Sep 13:27:34 ntpd[16798]: system event 'event_restart' (0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
14 Sep 13:27:43 ntpd[16798]: peer LOCAL(0) event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
14 Sep 13:30:55 ntpd[16798]: system event 'event_peer/strat_chg' (0x04) status 'sync_alarm, sync_local_proto, 2 events, event_restart' (0xc521)
14 Sep 13:30:55 ntpd[16798]: kernel time discipline status change 41
14 Sep 13:30:55 ntpd[16798]: system event 'event_sync_chg' (0x03) status 'leap_none, sync_local_proto, 3 events, event_peer/strat_chg' (0x534)
14 Sep 13:30:55 ntpd[16798]: system event 'event_peer/strat_chg' (0x04) status 'leap_none, sync_local_proto, 4 events, event_sync_chg' (0x543)
14 Sep 13:31:58 ntpd[16798]: kernel time discipline status change 1
14 Sep 14:27:34 ntpd[16798]: offset 0.000000 sec freq 8.386 ppm error 0.000011 poll 6
"
ntpq -p

# ntpq -p
remote refid st t when poll reach delay offset jitter
==============================================================================
*LOCAL(0) LOCAL(0) 11 l 4 64 377 0.000 0.000 0.008


結果(開発2号機):
ntpd.log
"
15 Sep 09:41:59 ntpd[19023]: system event 'event_restart' (0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
15 Sep 09:42:00 ntpd[19023]: peer LOCAL(0) event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
15 Sep 09:45:14 ntpd[19023]: system event 'event_peer/strat_chg' (0x04) status 'sync_alarm, sync_local_proto, 2 events, event_restart' (0xc521)
15 Sep 09:45:14 ntpd[19023]: synchronized to LOCAL(0), stratum 10
15 Sep 09:45:14 ntpd[19023]: kernel time sync disabled 0041
15 Sep 09:45:14 ntpd[19023]: system event 'event_sync_chg' (0x03) status 'leap_none, sync_local_proto, 3 events, event_peer/strat_chg' (0x534)
15 Sep 09:45:14 ntpd[19023]: system event 'event_peer/strat_chg' (0x04) status 'leap_none, sync_local_proto, 4 events, event_sync_chg' (0x543)
15 Sep 09:46:20 ntpd[19023]: kernel time sync enabled 0001
"

ntpq -p

remote refid st t when poll reach delay offset jitter
==============================================================================
*LOCAL(0) LOCAL(0) 10 l 5 64 377 0.000 0.000 0.004


エラーログは出力されなかったけれども、指定した時刻サーバーとは同期されませんでした。どうやら、minpollがmaxpollを上回る設定になっていると、時刻同期サーバーはLOCALとして動くようです(その他設定が間違っているときもそうなるのかはまた別の機会に調べます)。
カテゴリー: OSについて
投稿者: shinichi
先日、pam_tally.soの記述が二ファイル(loginとsystem-auth)に書かれていることで、ログイン失敗について厳しかったことが発覚した。

本番サーバーではsystem-authに記述していることもあり、開発の各サーバーでもログイン失敗のカウントはloginファイルではなく、system-authファイルに記述することに決めた。

作業は別に何をするわけでもなく、ただ、loginファイルに書かれている

"
auth required /lib/security/$ISA/pam_tally.so onerr=fail no_magic_root
account required /lib/security/$ISA/pam_tally.so per_user deny=3 no_magic_root reset
"

をsystem-authに書き写すだけ。

作業終了後、念のため動作確認をしてみた。telnetで接続し、わざと3回間違えてアカウントがロックされるかどうかを確認する。

RHEL3とRHEL4とで動作が違うことに気がついた。

RHEL3では、"deny=3"と設定すると「3回の間違いまでは許します」という動きに対し、
RHEL4では、"deny=3"と設定すると「3回失敗するとロックします」という動きだった。

当環境の詳細なバージョンは下記の通り
RHEL3(2.4.21-20)
pam(0.75)

RHEL4(2.6.9-43)
pam(0.77)

でも、"/usr/share/doc/pam-<version>/txts/README.pam_tally"に違いはないんだよなぁ・・・
カテゴリー: OSについて
投稿者: shinichi
ntpq -pでの表示でpolling間隔の時間表示が秒から分に変わったことを書きました。

今日は分から時に変わりました。

polling 14では時刻同期間隔は273分です。

# ntpq -p
remote refid st t when poll reach delay offset jitter
==============================================================================
*123.456.789.098 123.98.1.90 2 u 61m 273m 377 0.169 11.501 16.782
LOCAL(0) LOCAL(0) 11 l 24 64 377 0.000 0.000 0.004


polling 15になると同期間隔は9時間(546分)になります。

# ntpq -p
remote refid st t when poll reach delay offset jitter
==============================================================================
*123.456.789.098 123.98.1.90 2 u 175 9h 377 1.110 0.228 0.985
LOCAL(0) LOCAL(0) 11 l 24 64 377 0.000 0.000 0.008

273分ぶりに時刻調整をしたのにもかかわらず、ずれが0.228ミリ秒だったというのが驚きです。

polling 14から15になるまでに約半日かかりました。明日のうちには16になるのかな?
カテゴリー: OSについて
投稿者: shinichi
NTP関連ですが、ntpqというコマンドがあります。

これは、ntpデーモンを起動しているときに、自分のサーバーがどの時刻サーバーと同期をとっているのか、どれくらい時刻差があるのかを確認できるコマンドです。

maxpoll 16で同期するにはどれくらい時間がかかるのか実験しているのですが、pollingが12になってから表示が変化しました。when列とpoll列です。

# ntpq -p
remote refid st t when poll reach delay offset jitter
==============================================================================
*123.456.789.098 123.98.1.90 2 u 61m 68m 377 0.110 0.281 0.142
LOCAL(0) LOCAL(0) 11 l 24 64 377 0.000 0.000 0.008

polling 11まではこれらの数値は秒数で2の4乗(16)から11乗(2048)まで表示されるのですが、polling 12からは分数が表示されるようになりました。数字の後ろについている"m"はminuteのmです。上記では、polling間隔が68分で、前回同期をとってから61分経過していることを表しています。whenの値ははじめは秒数でカウントされていましたが、あるところから分でのカウントに変わっていました。境目はどこなんだろう?

ちなみに、2行目のLOCALは64秒間隔での同期です。

polling 16は約18時間なので18hと表示されるのでしょうか?現場のサーバーに仕込んであるので明日が楽しみです。

RHEL4で確認してあります。
カテゴリー: OSについて
投稿者: shinichi
先月、サーバーの時刻設定を行う作業を行い、手動で時刻サーバーと同期を取る手順を入れていた。

本番サーバーでの作業は作業手順書を書いて、オペレーターに引き継いで行わなければならないので、時刻調整の所で下記メッセージを確認するように手順を書いた。

"
DD MMM hh:mm:ss ntpdate[xxxxx]: step time server 123.456.789.098 offset -xx.xxxxxx sec
"

実際に作業をお願いしたらntpdateコマンドを実行したところで問い合わせの電話が鳴った。

"
DD MMM hh:mm:ss ntpdate[xxxxx]: step time server 123.456.789.098 offset -xx.xxxxxx sec
"
ではなく
"
DD MMM hh:mm:ss ntpdate[xxxxx]: adjust time server 123.456.789.098 offset -xx.xxxxxx sec
"
だけれども正常に作業が出来ているのか?と。

"step"か"adjust"かの違いなので大丈夫ですと答えた後にソースを調べてみた。
すると、調整した秒数が0.5秒以上か未満かで出力メッセージが変わることがわかりました。


ntpdate.h(64)
#define NTPDATE_THRESHOLD (FP_SECOND >> 1) /* 1/2 second */

ntpdate.c(1295)
if (always_step) {
dostep = 1;
} else if (never_step) {
dostep = 0;
} else {
absoffset = server->soffset;
if (absoffset < 0)
absoffset = -absoffset;
dostep = (absoffset >= NTPDATE_THRESHOLD || absoffset < 0);
}

if (dostep) {
if (simple_query || l_step_systime(&server->offset)) {
msyslog(LOG_NOTICE, "step time server %s offset %s sec",
stoa(&server->srcadr),
lfptoa(&server->offset, 6));
}
} else {
#if !defined SYS_WINNT && !defined SYS_CYGWIN32
if (simple_query || l_adj_systime(&server->offset)) {
msyslog(LOG_NOTICE, "adjust time server %s offset %s sec",
stoa(&server->srcadr),
lfptoa(&server->offset, 6));
}


調整幅が0.5秒未満の場合にはメッセージ"adjust time server・・・"が、0.5秒以上の場合にはメッセージ"step time server・・・"が表示されます。

"
[root@TESTSERVER root]# ntpdate -q 123.456.789.098
server 123.456.789.098, stratum 2, offset -0.000586, delay 0.02568
15 Sep 16:59:32 ntpdate[20923]: adjust time server 123.456.789.098 offset -0.000586 sec
[root@TESTSERVER root]# date
Tue Sep 15 16:59:36 JST 2009
[root@TESTSERVER root]# date 09151700
Tue Sep 15 17:00:00 JST 2009
[root@TESTSERVER root]# ntpdate -q 123.456.789.098
server 123.456.789.098, stratum 2, offset -15.117865, delay 0.02570
15 Sep 17:00:04 ntpdate[20926]: step time server 123.456.789.098 offset -15.117865 sec
[root@TESTSERVER root]# ntpdate 123.456.789.098
15 Sep 16:59:55 ntpdate[20927]: step time server 123.456.789.098 offset -15.117872 sec
[root@TESTSERVER root]# ntpdate -q 123.456.789.098
server 203.214.181.109, stratum 2, offset -0.000139, delay 0.02568
15 Sep 17:01:32 ntpdate[20932]: adjust time server 123.456.789.098 offset -0.000139 sec
[root@TESTSERVER root]# ntpdate 123.456.789.098
15 Sep 17:01:32 ntpdate[20932]: adjust time server 123.456.789.098 offset -0.000139 sec
"

上記のように、-qオプションをつけたときにもstepかadjustかを確認することが出来ます。

勉強になりました。
RHEL3/4で確認(ソースはRHEL5の物)
カテゴリー: OSについて
投稿者: shinichi
今朝、隣に座っている開発リーダーから質問があった。

「ねぇねぇ、この開発サーバーだけ、ログインに失敗するとfaillogに2カウントされるんだけど」

「?ん?どういう事?」と実演を見てみた。

"pam_tally.so"を設定していると"/var/log/faillog"というファイルが作成され、ログイン情報が記録される。
通常、ログインに失敗すると、失敗カウントが1ずつ増えていく。そして、設定した限界値に達するとその後のログインが出来なくなるわけです。
問題のサーバーでは通常1ずつ増えていく失敗カウントが2ずつ増えていくのです。

何か設定間違いをしてしまったのかと思い、"/etc/pam.d"にあるsystem-authファイルをチェックする。

"
auth required /lib/security/$ISA/pam_tally.so onerr=fail no_magic_root
account required /lib/security/$ISA/pam_tally.so per_user deny=3 no_magic_root reset
"
上記2エントリが追加されているだけで、怪しい箇所は見受けられない。一回のカウント数を決める箇所もないし・・・

少しググってみると、system-authに書く派とloginに書く派があることがわかったので、うちのサーバーのloginを見てみると・・・書いてありました。

サーバーの設定を変更する要件があって、僕はsystem-authに追加していたのですが、前任管理者はloginに追加していたのです。知らなかった・・・

デフォルトのloginにはpam_tally.soの記述など無く、設定は全てsystem-authを参照してねという
"
pam_stack.so service=system-auth
"
が全てのエントリについて記述されている。

通常は全ての動作はsystem-authを見てそれに従う設定になっています。

今回の事象ではまず、loginを読み込んでfaillogに1追加し、次にsystem-authを読み込んでfaillogに1追加するので、全体としては2追加されることになっていたのです。

loginからpam_tally.soのエントリを削除して解決です。

もう一つ罠が仕掛けられていました。"deny=2"と設定されていたのです。一回間違えると失敗カウントが2になり、限界値2に達し、その後はログイン出来なくなってしまいます・・・あぁつかいずらいサーバーだったこと

カテゴリー: OSについて
投稿者: shinichi
logconfigの設定についてで思いついた"logconfig +syscall"の動きを試した。

時刻が調整されているサーバーでntpdを停止後、dateコマンドで時刻を2分ほどずらした。そしてntpdの起動を行い、下記のログが出力された。

"
10 Sep 10:15:09 ntpd[11346]: running as uid(38)/gid(38) euid(38)/egid(38).
10 Sep 10:18:42 ntpd[11346]: time reset 139.316135 s
10 Sep 10:18:42 ntpd[11346]: kernel time discipline status change 41
10 Sep 10:18:42 ntpd[11346]: synchronisation lost
10 Sep 10:20:23 ntpd[11346]: kernel time discipline status change 1
"

"time reset 139.316135 s"。前回予想したとおり、システムクロックに関するログが出力されるんだ。

今回のログで出力された"synchronisation lost"はソースを検索しても出てこないのだが、時刻がステップ調整されると一旦時刻サーバーとの接続がとぎれるらしい。その後、"kernel time discipline status change 1"が出ており、nptqコマンドで時刻同期が取れているので今のところはよしとする。

相変わらずRHEL3/4で確認。
カテゴリー: OSについて
投稿者: shinichi
NTPの設定について③でよくわからずに設定した"logconfig"について試してみました。

"logconfig +syscall"
8 Sep 19:00:59 ntpd[14904]: running as uid(38)/gid(38) euid(38)/egid(38).
8 Sep 19:01:59 ntpd[14904]: kernel time discipline status change 41
8 Sep 19:02:34 ntpd[14904]: kernel time discipline status change 1

"logconfig +clockall"
8 Sep 19:00:57 ntpd[14110]: running as uid(38)/gid(38) euid(38)/egid(38).
8 Sep 19:01:57 ntpd[14110]: kernel time discipline status change 41
8 Sep 19:02:32 ntpd[14110]: kernel time discipline status change 1

"logconfig +peerall"
8 Sep 19:01:00 ntpd[511]: peer 123.456.789.098 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
8 Sep 19:01:01 ntpd[511]: peer LOCAL(0) event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
8 Sep 19:02:33 ntpd[511]: synchronized to 123.456.789.098, stratum 2
8 Sep 19:02:33 ntpd[511]: kernel time sync disabled 0041
8 Sep 19:09:04 ntpd[511]: kernel time sync enabled 0001

"logconfig +sysall"
8 Sep 19:00:58 ntpd[7444]: running as uid(38)/gid(38) euid(38)/egid(38).
8 Sep 19:00:58 ntpd[7444]: system event 'event_restart' (0x01) status 'sync_alarm, sync_unspec, 1 event, event_unspec' (0xc010)
8 Sep 19:01:06 ntpd[7444]: peer LOCAL(0) event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
8 Sep 19:01:09 ntpd[7444]: peer 123.456.789.098 event 'event_reach' (0x84) status 'unreach, conf, 1 event, event_reach' (0x8014)
8 Sep 19:01:58 ntpd[7444]: system event 'event_peer/strat_chg' (0x04) status 'sync_alarm, sync_ntp, 2 events, event_restart' (0xc621)
8 Sep 19:01:58 ntpd[7444]: kernel time discipline status change 41
8 Sep 19:01:58 ntpd[7444]: system event 'event_sync_chg' (0x03) status 'leap_none, sync_ntp, 3 events, event_peer/strat_chg' (0x634)
8 Sep 19:01:58 ntpd[7444]: system event 'event_peer/strat_chg' (0x04) status 'leap_none, sync_ntp, 4 events, event_sync_chg' (0x643)
8 Sep 19:02:33 ntpd[7444]: kernel time discipline status change 1
8 Sep 20:00:58 ntpd[7444]: offset 0.000020 sec freq 27.469 ppm error 0.000079 poll 5
8 Sep 21:00:58 ntpd[7444]: offset 0.001049 sec freq 23.676 ppm error 0.000335 poll 6
8 Sep 22:00:58 ntpd[7444]: offset 0.000274 sec freq 23.906 ppm error 0.000411 poll 8
8 Sep 23:00:58 ntpd[7444]: offset 0.000842 sec freq 23.919 ppm error 0.000359 poll 10
9 Sep 00:00:58 ntpd[7444]: offset 0.007946 sec freq 23.954 ppm error 0.002036 poll 10
9 Sep 01:00:58 ntpd[7444]: offset 0.020403 sec freq 24.032 ppm error 0.004302 poll 10
9 Sep 02:00:58 ntpd[7444]: offset 0.005241 sec freq 25.256 ppm error 0.002214 poll 9
9 Sep 03:00:58 ntpd[7444]: offset 0.002397 sec freq 25.342 ppm error 0.001221 poll 10
9 Sep 04:00:59 ntpd[7444]: offset 0.003058 sec freq 25.386 ppm error 0.000715 poll 10
9 Sep 05:00:59 ntpd[7444]: offset 0.004596 sec freq 25.436 ppm error 0.000736 poll 9
9 Sep 06:00:59 ntpd[7444]: offset 0.000054 sec freq 25.811 ppm error 0.000558 poll 9
9 Sep 07:00:59 ntpd[7444]: offset 0.002246 sec freq 25.838 ppm error 0.000567 poll 10
9 Sep 08:00:59 ntpd[7444]: offset 0.001653 sec freq 25.885 ppm error 0.000350 poll 9
9 Sep 09:00:59 ntpd[7444]: offset 0.000101 sec freq 25.960 ppm error 0.000172 poll 10

試してみて気がついたのは、syscallとclockallはそれぞれシステムクロックとハードウェアクロックについてのログレベルではないか?ということ。今回試したのは時刻同期をしているサーバーでntp.confを書き換えてntpdを再起動しただけなので、大幅な時刻調整は入っていない。そのため、ログには起動についてのログしか出ていないのではないか?

peerallは接続先サーバーの状態と、それに対応する自サーバーの状態についてのログレベルではないか?ということ。このレベルで初めて"synchronized to・・・"が記録されている。

sysallは上記全てを含んだログレベルではないか?ということ。で、それにプラスしてdriftfileへの書き込みについてのログを出している(ちなみに、毎時driftfileが変更されていることが確認できる)。

また少しずつ調べていきます。
カテゴリー: OSについて
投稿者: shinichi
NTPの設定について①
NTPの設定について②の続き

各種設定の意味を調べてから新しくntp.confを書き直しました。

"
tinker panic 0

restrict default ignore
restrict 127.0.0.1
restrict 123.456.789.0 mask 255.255.255.0 nomodify notrap

server 123.456.789.098 minpoll 4 maxpoll 8
server 123.456.789.097 minpoll 4 maxpoll 8

server 127.127.1.0
fudge 127.127.1.0 stratum 11

driftfile /var/lib/ntp/drift
logconfig +syscall +clockall +sysall +peerall
logfile /var/log/ntpd.log
"
まず、ntpデーモンが自動的に終了しないように設定。
"restrict 123.456.789.0 mask 255.255.255.0"で同一LAN内でのアクセスを可能に。後のオプションは他のサーバーからアクセスが来たときに変更されることがないようにする物のようです(要調査)。

今回は参照時刻サーバーを二カ所設定していて、時刻調整間隔は短めの4から8にしてあります。今まで10に設定していて、ntpが動いている間に30秒もずれていたので、間隔を少し短くすることになりました。本番機だからどんな具合なのか見ることができずに残念です。

"logconfig"で指定すると詳細なログが出力されるようになります。どのオプションをつけるとどれだけ変わるのかはまだ未調査ですが、とりあえず全部乗せでいきました(要調査)。

"logfile"には起動/停止・最初に調整した時のずれ幅とdriftファイルを更新したログが出力されます。ログを見ると、driftファイルが一時間ごとに修正されていることがわかります。

ntp.confを書き換えたらntpdを再起動すれば作業完了です。新しい設定を読み込んで動いてくれます。
カテゴリー: OSについて
投稿者: shinichi
NTPの設定について①の続き

ntp.confの書き方。
"restrict"は接続サーバーを指定するのに使います。接続する先についても、接続してくる元についても書く必要があります。

"restrict default ignore"でまず、どこからのアクセスも拒否します(はじめに一切合切拒否するのはセキュリティ設定ではふつうのことです)。

"restrict 127.0.0.1"でローカルホストからのアクセスを許可します。これは、時刻サーバーにつながらないときには127.127.0.0をstratum 12の時刻サーバーとして時刻調整をする動きとなるので必要です。

"restrict 123.456.789.098"でこちらがアクセスする時刻サーバー/自サーバーを時刻サーバーとしてアクセスしてくるサーバーのIPを記述します。サーバー名で指定することも出来ますが、hostsファイルへの参照が必要になるのでIPの方が早いとのこと。

"server 123.456.789.098 minpoll 9 maxpoll 10"で時刻サーバーへの同期間隔を指定します。
"minpoll"で最短間隔を指定します。
"maxpoll"で最長間隔を指定します。
minpoll/maxpollを指定しない場合、minpollが64秒、maxpollが1024秒に設定されます。

同期感覚は3~17までを指定することが出来ます。また、指定した数字が直接秒数になるわけではなく、ここで指定する数字は2の指数となります。ですので、設定可能範囲は2^3秒(8秒)~2^17秒(約36時間)となります。

"fudge 127.127.0.0 stratum 12"で時刻サーバーと通信が出来ない場合に自サーバーを一時的に時刻サーバーと認識させます。stratumは時刻サーバーのランクで、最高が1になります。NICTの時刻サーバーなどがstratum1となり、NICTを参照している時刻サーバーがstratum2となり・・・と、一番正確な時刻サーバーから離れるにつれて数字が大きくなっていきます。

"driftfile /var/lib/ntp/drift"では自分のクロック周波数を記録しておくファイルを指定します。指定した時刻サーバーにアクセスできない場合には自分が仮の時刻サーバーになるからです。このファイルは毎時間更新されます。

RHEL3/4で確認