Agent のトレース
Tracing クラスを用いて Agent を含めたプログラムの挙動を確かめることができる / seeing how Agent works with EOS by using Tracing class
(verified 2010 Feb. / EOS 4.3.0 / DCS-7120T-4S 03.01)
トレース機能の埋め込み
Agent として機能しているプログラムには内部的な実行状態を追跡するための Tracing 機能が用意されている。
具体的には Agent プログラム中には予め trace0( ) など名前が trace で始まるトレース用関数の呼び出しが埋め込まれている。これらの関数はシステムワイドに設定可能なトレース状態ビットの on / off を参照し、それが off（通常状態）では呼び出されても何の効果も無いように作られている。そして on の際には呼び出されるたびにトレースログを出力する。
本稿ではトレース機能を設定した状態でシステム状態に変化を起こし、その際に Agent プログラムがどのような挙動をとるか追跡する方法を示す。システム状態を変化させる簡単な方法としてファンの引き抜き、差し戻しを利用する。つまりファン を引き抜いた時に、それを監視している Thermostat Agent がどのように振る舞うかを調べる。
Thermostat Agent におけるトレース関数利用の実際
まず Thermostat Agent の存在を確認する。
$ ps -ef --forest
UID PID PPID C STIME TTY TIME CMD
....
root 1 0 0 Mar11 ? 00:00:34 /sbin/init
....
root 1473 1 0 Mar11 ? 00:00:00 ProcMgr-mast
root 1478 1473 0 Mar11 ? 02:41:55 \_ ProcMgr-work
....
root 1522 1478 0 Mar11 ? 01:17:10 \_ Thermostat
また後述するが、Thermostat Agent が Process Manager から呼び出されている点に注目。
Thermostat エージェントの実体は /usr/bin/Thermostat にある Python スクリプトである。
そこでは単に Thermostat クラスをロードして起動することしか書かれていない。
エージェントの本体、Thermostat クラスなどは /usr/lib/python2.5/site-packages/ 以下にある。
冒頭部に以下のような記述がある。
bash-3.2# cat /usr/lib/python2.5/site-packages/Thermostat.py
....
import Tracing
__defaultTraceHandle__ = Tracing.Handle( 'Thermostat' )
t0 = Tracing.trace0 # Traces the fan speed algorithm
t1 = Tracing.trace1 # Traces configuration changes from the user
t3 = Tracing.trace3 # Cooling alarm level changes
t7 = Tracing.trace7
t8 = Tracing.trace8 # fru shutdown messages
t9 = Tracing.trace9
（.... 以下略）
つまり Tracing クラスを import し、t0 から t9 までの名前で Tracing クラスが用意したトレース関数群に別名をつけている。
更に Thermostat.py のコードを眺めると、例えば以下のようにしてこれらのトレース関数が呼ばれている箇所が多数見つかる。
def _handleTimeout( self ):
t0( "FanSpeedAlgorithm: start" )
つまり上記コードは関数 _handleTimeout() が呼び出されると必ず一度、t0() 関数（その実体は Tracing クラスの trace0() 関数）が "FanSpeedAlgorithm: start" メッセージ付きで呼び出されることを意味する。
最終的にはこのメッセージはログとして出力される。
トレース状態の設定
Tracing クラス
Tracing クラスの実体は /usr/lib/python2.5/site-packages/Tracing.py にある。冒頭に以下のような記述がある。
To use this module::
import Tracing
Tracing.trace3( "some message at level 3" )
Each of the trace<n> functions takes a variable number of arguments, which are
converted to strings using str() and concatenated to form the final trace string.
つまりトレース機能を利用するには単に Tracing クラスを import して、レベルに応じた trace ログ出力関数を呼び出すだけである。
トレースの on/off 制御についてもすぐ次に書かれている。
主に二つ方法があり、一つは TRACE 環境変数を設定するもので、もう一つは TRACE コマンドを利用する方法である。
* Using the TRACE, TRACEFILE and TRACEFORMAT environment variables, like this::
export TRACE=*/01,Ebra/*,Fru/3,Artest*/1-5
export TRACEFILE=/tmp/trace.out
export TRACEFORMAT=time,file/15,func,line-number
This example turns on levels 0 and 1 for all facilities, all levels for Ebra,
level 3 for Fru, and levels 1 to 5 for any facility that starts with "Artest".
......（略）
* Using the Tracing CLI to modify the configuration of a running agent.
bash からスクリプトを起動する場合には環境変数の設定が容易であるが、実行途中の Agent に介入するには後者の TRACE コマンドを Arista CLI から実行する方が簡単である。
なお先に示したように Thermostat.py の t0() 関数などはこの Tracing クラスの trace0() 関数などの別名として用意されたりする。
TRACE コマンド
まず enable モードから configure モードに移行する。
localhost> enable
localhost# configure
localhost(config)#
次に現状確認のために SHOW TRACE する。Thermostat など Agent の名前を与える必要がある。
localhost(config)#show trace Thermostat
Global trace settings for agent Thermostat
-----------------------------------------------
Tracing sent to stderr
date: enabled
time: enabled
PID: enabled
facility name: enabled (width 20)
trace level: enabled <=== ★1
filename: disabled (width 20)
line number: disabled
function name: disabled (width 20)
object name: disabled (width 20)
Trace facility settings for agent Thermostat
-----------------------------------------------
Activity enabled ............
Agent enabled ............
.... 中略 .....
Thermostat enabled ............ <== ここに注目
....
★1. この項目（trace level）では個別のトレースレベルを決めるのではなくトレース関数に与えられたメッセージをログに含めるかどうかを設定するだけ
Thermostat agent の状態が enabled になっているが、実際にはこの後ろのピリオドの列が重要。
以下のように TRACE コマンドで Thermostat Agent の Level 0 のトレースを enable にすることができる。
localhost(config)#trace Thermostat enable Thermostat levels 0
この結果、show trace Thermostat の後半の結果が、
Thermostat enabled ............
から、
Thermostat enabled 0...........
に変わる。
これを再び外すには以下のようにする。
localhost(config)#no trace Thermostat enable Thermostat levels 0
ピリオドと 0 の表示が少し見慣れないが、0 が当該レベルの on、ピリオドが off を意味している。
level 1 を on にすると以下のような表示になる。
Thermostat enabled .1..........
つまりトレース状態の設定は、level という名前ながら数値を上下させてログの詳細度を調整するような考え方をしておらず、各 level ごとに個別の内容についてのログを出し、それらを個別に on/off 設定するようになっている。（Thermostat.py の場合について先に示した）
設定可能なレベル（ピリオドの数から推定できるように 12 種）の種類（名前）は以下のように TRACE コマンドのヘルプメッセージから得られる。
localhost(config)#trace Thermostat enable Thermostat levels ?
0 Enable tracing at level 0
1 Enable tracing at level 1
2 Enable tracing at level 2
3 Enable tracing at level 3
4 Enable tracing at level 4
5 Enable tracing at level 5
6 Enable tracing at level 6
7 Enable tracing at level 7
8 Enable tracing at level 8
9 Enable tracing at level 9
coverage Enable tracing at level coverage
function Enable tracing at level function
つまり 0-9 と、coverage, function である。
なお後ろ二つ（coverage, function）については良く分からない。
trace Thermostat enable Thermostat levels coverage
とやって設定すると、単純に
Thermostat enabled ..........c.
となる。何だろう？
メッセージログ
TRACE コマンドによってトレースログ出力が設定された場合、/var/log/agents/ 以下にテキストファイルでログが残る。ファイル名は Agent-pid である。
例えば trace Thermostat enable Thermostat levels 0 とした場合、5 sec おきに下記のようなログが出ている。
[admin@localhost tmp]$ cat /var/log/agents/Thermostat-32378
2009-02-25 18:26:17.062900 32378 Thermostat 0 FanSpeedAlgorithm: start
2009-02-25 18:26:17.068373 32378 Thermostat 0 FanSpeedAlgorithm: setting fan Fan2/1 to 38 based on max inlet temperature
2009-02-25 18:26:17.068891 32378 Thermostat 0 FanSpeedAlgorithm: setting fan Fan4/1 to 38 based on max inlet temperature
2009-02-25 18:26:17.069364 32378 Thermostat 0 FanSpeedAlgorithm: setting fan Fan3/1 to 38 based on max inlet temperature
2009-02-25 18:26:17.069822 32378 Thermostat 0 FanSpeedAlgorithm: setting fan Fan1/1 to 38 based on max inlet temperature
2009-02-25 18:26:17.070279 32378 Thermostat 0 FanSpeedAlgorithm: setting fan Fan5/1 to 38 based on max inlet temperature
ソースとの対照
先述のログとソースコードを対照することで Agent の振る舞いを追跡することができる。
以下に Thermostat.py のコードを引用して例示する。
まず "based on max inlet temperature" テキストをソースコードから捜すと以下のように ThermostatConfigReactor クラスの _handleTimeout() 関数に含まれていることがわかる。
class ThermostatConfigReactor( Fwk.Notifiee ):
.......
def _handleTimeout( self ):
t0( "FanSpeedAlgorithm: start" )
.........
for fanConfig in self.coolingConfig_.fan.values():
............
fanConfig.speed = fanSpeed
t0( "FanSpeedAlgorithm: setting fan", fanConfig.name, "to", fanSpeed,
"based on max inlet temperature" )
この関数の冒頭にある "FanSpeedAlgorithm: start" メッセージもやはりログに出ており、5 秒おきにこの関数が呼ばれていることがわかる。
また、このとき fanConfig.name や fanSpeed 変数の値がどのようなものであったか確認できる。
イベントの発生
この状態でファンを引き抜くことによって、ソース上のどこを通過するようになったのか確認することが出来る。実際に抜いたところ以下のようなログが出るようになった。
2009-02-25 18:37:08.995441 1139 Thermostat 0 FanSpeedAlgorithm: start
2009-02-25 18:37:08.999087 1139 Thermostat 0 FanSpeedAlgorithm: cooling alarm level is fanTrayFailedOrMissing setting fans to full speed
つまり今度は（上記同様に _handleTimeout() 関数にある）以下の記述に分岐した。
elif systemCoolingAlarmLevel != "coolingOk":
t0( "FanSpeedAlgorithm: cooling alarm level is", systemCoolingAlarmLevel,
"setting fans to full speed" )
_configureAllFans( 100 )
また、このとき systemCoolingAlarmLevel 変数の値が "fanTrayFailedOrMissing" であったことも確認できる。なお直下に _configureAllFans( 100 ) とあり、このためにファンは 100% 全力で回り始める。（EOS コマンド show environment cooling によって確認できる）
トレースポイントの追加
より詳細にソース中のどこを通過するか、あるいは通過時の変数の内容を把握したい場合があり得る。その場合は trace() 関数を追加するなどして Agent を再起動すれば良い。具体的な方法を以下に示す。
コードの修正
以下は安全のために Thermostat.py を /tmp ディレクトリに移して内容を修正した例である。
bash-3.2# cp /usr/lib/python2.5/site-packages/Thermostat.py /tmp/
bash-3.2# vi /tmp/Thermostat.py
bash-3.2# diff /tmp/Thermostat.py /usr/lib/python2.5/site-packages/Thermostat.py
1479c1479
< t0( "FanSpeedAlgorithm: start ***" )
---
> t0( "FanSpeedAlgorithm: start" )
bash-3.2#
今回はプログラムを修正する手順を示すことが目的なので、ログにメッセージが残ることを（先述の通り）確認した t0() 関数のメッセージ部分を変更するにとどめた。実際には t0() 関数呼び出しを望みの箇所に追加する場合が多いだろう。
read write モードでの再マウント
修正が済めば本物の Thermostat.py に上書きコピーするのだが、対象となるディレクトリは read only モードでマウントされているため、コピーの前に read write モードで再マウントする必要がある。
bash-3.2# mount -o,rw,remount /
bash-3.2# cp /tmp/Thermostat.py /usr/lib/python2.5/site-packages/Thermostat.py
bash-3.2#
なお Python の特性上、同ディレクトリに .pyo, .pyc のコンパイル済みコードが置かれている。これらのファイルは更新日付がソースコードより古いため無視されるが、気になるようなら削除しておけば良い。
Agent の再起動
更新が反映されれば Agent プログラムを停止させる。単に ps コマンドで pid を調べ、kill で停止すれば良い。
bash-3.2# ps -ef | grep Thermostat
root 1522 1478 0 Mar11 ? 01:17:49 Thermostat
root 6224 6103 0 19:39 pts/2 00:00:00 grep Thermostat
bash-3.2# kill 1522
bash-3.2#
しかし kill した直後であっても別 pid で再び Thermostat Agent が確認されるだろう。
bash-3.2# ps -ef | grep Thermostat
root 6226 1478 54 19:39 ? 00:00:00 Thermostat
root 6229 6103 0 19:39 pts/2 00:00:00 grep Thermostat
bash-3.2#
これは Process Manager によって Agent の停止が検出され、再起動されたためである。（Agent が Proc-Mgr によって起動されていたことを ps の --forest オプションで確認した事を思い出されたし。）
その経過は messages ファイルにログとして残る。
bash-3.2# tail /var/log/messages
......
Apr 13 19:39:53 localhost ProcMgr-worker: %PROCMGR-6-PROCESS_TERMINATED: 'Thermostat' (PID=1522) has terminated.
Apr 13 19:39:53 localhost ProcMgr-worker: %PROCMGR-6-PROCESS_RESTART: Restarting 'Thermostat' immediately (it had PID=1522)
Apr 13 19:39:53 localhost ProcMgr-worker: %PROCMGR-6-PROCESS_STARTED: 'Thermostat' starting with PID=6226 (PPID=1478) -- execing '/usr/bin/Thermostat'
bash-3.2#
Trace 状態の再設定
Agent の停止によって trace コマンドで設定したトレースレベルが全て off 状態に戻されることに注意が必要である。
これについては再び trace Thermostat enable Thermostat levels 0 などとして設定し直すしかない。
設定によって再び /var/log/agents/ 以下に新しい pid をファイル名の一部にもつログファイルが作成される。
bash-3.2# ls /var/log/agents/Thermostat-*
/var/log/agents/Thermostat-1522 /var/log/agents/Thermostat-6226
bash-3.2#
このログの中身を見れば、先のソースコードの修正が反映されたことが確認できる。（最初のログの start の後に *** があることに注目）
bash-3.2# cat /var/log/agents/Thermostat-6226
==== Output from /usr/bin/Thermostat [] (PID=6226) started Apr 13 19:39:53 ===
2009-04-13 19:43:53.667903 6226 Thermostat 0 FanSpeedAlgorithm: start ***
2009-04-13 19:43:53.673337 6226 Thermostat 0 FanSpeedAlgorithm: setting fan Fan2/1 to 37 based on max inlet temperature
2009-04-13 19:43:53.673852 6226 Thermostat 0 FanSpeedAlgorithm: setting fan Fan4/1 to 37 based on max inlet temperature
......
read only モードでの再マウント
再び安全のために read only モードで再マウントする。
bash-3.2# mount -o,ro,remount /
bash-3.2#
もし read only での再マウントを Agent の起動に先立って行った場合、.pyc ファイル（コンパイル済みコード）が残らない。（以下は正常にコンパイル結果が残された例）
bash-3.2# ls -l /usr/lib/python2.5/site-packages/Thermostat.*
-rw-r--r-- 1 root root 75613 Apr 13 19:29 /usr/lib/python2.5/site-packages/Thermostat.py
-rw-r--r-- 1 root root 52723 Apr 13 19:58 /usr/lib/python2.5/site-packages/Thermostat.pyc
-rw-r--r-- 1 root root 52022 Nov 22 2009 /usr/lib/python2.5/site-packages/Thermostat.pyo
bash-3.2#
しかしこれは問題にならない。Agent 再起動の際にシステム負荷が若干上がるが、システム全体をリブートすれば、すべての結果は再び初期状態に戻る。
つまりもし更新した Agent をリブート後にも有効にしたい場合は別途作業が必要である。
（これについては Extenions および 起動イメージの変更・Aboot を参照）
