SMS日志分析开发笔记01 —— 日志解析
日志文件位置
SMS 以文件形式保存日志，默认路径在 %SMSHOME%/%SMSLOG%，可以使用环境变量 SMSLOG 在 SMS 启动前设置日志文件的位置和名称。下面是我们一个 SMS 服务的变量
所以 SMS 日志就保存在在 /cma/u/nwp/smsworks/sms/cma20n03.check 文件中。该文件的内容如下：
如果 SMS 运行时日志文件存在，则继续追加到该文件，否则，SMS 会自动创建日志文件。
日志内容
日志文件包含 SMS 服务器的所有动作，并显示诸如用户登录时间等信息。
它是一个纯文本文件，可以很方便地被其他程序处理。例如，XCDP 使用该文件显示 timeline 窗口。
日志文件的格式非常简单。SMS 中的每个动作都会生成一行。格式如下：
其中，XXX 是下表中的一个标记。[] 中的 timestamp是系统时间，不是 suite 时间，两者可能不同。
<td>
含义
</td></thead>
<tr>
<td>
MSG
</td>
<td>
用户动作、常规操作生成的信息
</td>
</tr>
<tr>
<td>
LOG
</td>
<td>
task 或 SMS、常规操作生成的信息。最常见的消息就是节点的状态改变。
</td>
</tr>
<tr>
<td>
ERR
</td>
<td>
错误消息，无法完成的非常规操作。某些操作在客户端被忽略，如尝试发送SMS中不存在的 label 或 event 对 SMS 端来说就是一个错误，但在客户端则不是。
</td>
</tr>
<tr>
<td>
WAR
</td>
<td>
警告消息，不是错误但校正后的操作被执行。例如，使用旧版本客户端会产生一条警告记录。
</td>
</tr>
<tr>
<td>
DBG
</td>
<td>
调试信息，默认不显示，必须由管理员打开。
</td>
</tr>
<tr>
<td>
others
</td>
<td>
如果 SMS 以交互模式运行，日志中可能会记录键盘输入。处理日志的程序应该忽略这些行。
</td>
</tr></table>
<p>
注意：用户命令通常会产生 MSG 和 LOG 两种类型的消息。MSG 记录命令执行，LOG 记录该命令对节点的效果。<br /> 注意：日志文件不会被自动删除，所以需要管理。我们倾向于使用一个受 SMS 控制的脚本每天压缩并归档我们的日志文件。<br /> 操作主要由 command 区分，下面简要介绍不同的 command 对应的日志条目。
</p>
<h2>
日志条目command详细分析
</h2>
<p>
因为日志中的每条记录都以’# ‘开头，所以下面示例中将其省略。
</p>
<h3>
节点状态
</h3>
<p>
节点状态类日志一般成批出现，子节点状态改变时，沿节点树向上到根节点的每个节点的状态也可能改变。
</p>
<h4>
queued
</h4>
<pre>LOG:[10:01:14 24.4.2015] queued:/gda_gsi_v1r5/T639/00/obs/obs_get
LOG:[10:01:14 24.4.2015] queued:/gda_gsi_v1r5/T639/00/obs LOG:[10:01:14 24.4.2015] queued:/gda_gsi_v1r5/T639 LOG:[10:01:14 24.4.2015] queued:/gda_gsi_v1r5 LOG:[10:01:14 24.4.2015] queued:/
<h4>
submitted
</h4>
<h4>
active
</h4>
<h4>
complete
</h4>
<h4>
aborted
</h4>
<p>
等等命令
</p>
<h3>
变量
</h3>
<h4>
alter
</h4>
<p>
改变节点，比如变量等，cdp 中使用 alter 命令会记录 alter 条目
</p>
<pre>MSG:[10:01:00 24.4.2015] alter:/gda_gsi_v1r5/T639/00/obs/atovs_get [variable] by nwp@15
MSG:[01:51:03 18.9.2015] alter:/windroc_cdp/cdp/show [variable] by wangdp@73026 WAR:[01:55:07 18.9.2015] alter:option -d[date] not implemented yet MSG:[01:55:07 18.9.2015] alter:/windroc_cdp [date] by wangdp@73027
<h4>
meter
</h4>
<p>
正常记录（LOG）
</p>
<pre>LOG:[12:17:19 24.4.2015] meter:/gmf_gsi_v1r5/T639/06/model/forecast_10d:completed to 340</pre>
<p>
错误记录（ERR）
</p>
<pre>ERR:[03:41:58 10.7.2014] meter:WaitingMins for /grapes_meso_v4_0/cold/00/pre_data/obs_get/aob_get:the node was not found:
ERR:[12:52:00 19.5.2014] meter:/gmf_gsi_v1r5/T639/06/dasrefresh:WaitingMins: 55 out of range [0 - 40]
<h4>
event
</h4>
<p>
一般在出错的时候才有
</p>
<pre>ERR:[00:23:36 1.10.2014] event:actived for /gmf_gsi_v1r5/T639/18/model/mod_gf:the node was not found:</pre>
<h4>
set
</h4>
<p>
设置事件（event）
</p>
<pre>LOG:[23:49:24 10.11.2014] set:/gmf_gsi_v1r5/T639/18/obs/sst_make:sstready</pre>
<h4>
clear
</h4>
<p>
取消事件（event）
</p>
<pre>LOG:[03:14:01 21.9.2014] clear:/gda_ssi_v1/T213/12/obs/tcreport_get:arrived</pre>
<p>
等等命令
</p>
<h3>
节点干预操作
</h3>
<h4>
force</h3>
<p>
强制设置节点状态，包括使用kill命令杀掉任务
</p>
<pre>MSG:[00:36:05 7.10.2014] force:/grapes_meso_v4_0/cold/12/model/fcst to queued by nwp@10848782
MSG:[21:24:37 21.9.2014] force:/extend_v2_1/subsys/uvi/12/uvi to complete by nwp@10493355 MSG:[03:21:18 13.9.2014] force:/obs_reg/aob/00E/obs_get/getobs_rgwst to aborted by nwp@10266057
<h4>
delete
</h4>
<p>
删除依赖关系（包括 trigger、date、time 等），用于补做
</p>
<pre>MSG:[04:17:51 7.10.2014] delete:/gmf_gsi_v1r5/T639/00 time by nwp@10655492
MSG:[12:40:08 26.4.2015] delete:/grapes_meso_v4_0/cold/housekeep triggers by nwp@1
<h4>
requeue
</h4>
<p>
重新排队，用于补做，例如从 aborted 状态 requeue
</p>
<pre>WAR:[23:37:08 16.8.2015] requeue:/gmf_grapes_v1423/grapes_global/12/post/postp_084 from aborted
MSG:[23:37:08 16.8.2015] requeue:user nwp@5986333:/gmf_grapes_v1423/grapes_global/12/post/postp_084
<h4>
run
</h4>
<p>
重新运行，在 XCDP 界面中执行 excute
</p>
<pre>LOG:[03:08:02 18.6.2014] run:/gda_ssi_v1/T213/18/an/ssi by nwp@7797433</pre>
<h4>
cancel
</h4>
<p>
取消节点，用于重新部署任务
</p>
<pre>LOG:[10:27:11 31.3.2014] cancel:/gmf_gsi_v1r5/T639/00/prods/grib2/grads2grib2_000/alias0 by nwp@5801977
LOG:[02:56:54 9.4.2014] cancel:/gda_gsi_v1r5 by nwp@6018242
<h4>
suspend
</h4>
<p>
挂起节点
</p>
<pre>MSG:[23:56:07 2.1.2015] suspend:/gda_grapes_v1423/grapes_global/12/model/fcst at status queued
MSG:[23:56:07 2.1.2015] suspend:/gda_grapes_v1423/grapes_global/12/model/fcst by nwp@34167272
<h3>
非常用命令
</h3>
<h4>
autorepeat date
</h4>
<p>
更新时间，后面接begin
</p>
<pre>MSG:[03:31:30 19.9.2014] autorepeat date:/gda_gsi_v1r5 started</pre>
<h4>
begin
</h4>
<p>
紧随autorepeat date，任务开始
</p>
<pre>MSG:[02:32:29 29.6.2014] begin:/grapes_meso_3_3 started automatically</pre>
<h4>
abort
</h4>
<p>
自动重做时记录的日志，与 aborted 一同出现
</p>
<pre>WAR:[00:45:17 7.10.2014] abort:/gmf_gsi_v1r5/T639/18/dasrefresh ---> try number 1</pre>
<h3>
系统命令
</h3>
<h4>
checkpoint
</h4>
<p>
保存运行状态
</p>
<pre>LOG:[03:31:30 19.9.2014] checkpoint:written into cma20n03.check by SMS</pre>
<h4>
login
</h4>
<p>
用户登录
</p>
<pre>MSG:[00:23:35 1.10.2014] login:User nwp@10719460 with password from cma20n03</pre>
<h4>
logout
</h4>
<p>
用户登出
</p>
<pre>MSG:[00:23:35 1.10.2014] logout:User nwp@10719460</pre>
<h4>
timeout
</h4>
<pre>WAR:[00:03:04 9.11.2014] timeout:user nwp@11617341 timed out</pre>
<h4>
zombie
</h4>
<pre>WAR:[11:54:40 19.5.2014] zombie:created new network zombie /gda_ssi_v1/T213/00/obs/tcreport_get from cma18n04 sender cma20n03</pre>
<h3>
内部日志
</h3>
<h4>
进程
</h4>
<h5>
非结构化PID
</h5>
<p>
进程出错，后面紧跟 aborted
</p>
<pre>ERR:[03:40:31 8.7.2014] PID 14352534 exited with status 127 [llsubmit2 /cma/g1/nwp/SMSOUT/gmf_ssi_v1/T213/00/obs/atovs_get.job2 /gmf_ssi_v1/T213/00/obs/atovs_get]</pre>
<h5>
SMS-PROCESS-SYS
</h5>
<h5>
SMS-PROCESS-CHILD
</h5>
<h4>
认证
</h4>
<h5>
SMS-PROG-1
</h5>
<pre>ERR:[00:44:01 8.4.2014] SMS-PROG-1:User 1050695,10506 from cma18n01 not registered</pre>
<h3>
其他
</h3>
<h4>
check
</h4>
<pre>MSG:[09:01:04 4.4.2014] check:method time interval 120 sec by nwp@5901621</pre>
<h4>
dir
</h4>
<pre>ERR:[03:46:56 17.6.2015] SMS-FILE-READ2: /cma/g1/nwp/SMSOUT/grapes_meso_v4_0/cold/00/pre_data/gmf_get/gmf_get_075.2:file was not found:
ERR:[03:46:56 17.6.2015] file:user was nwp@1163994 ERR:[03:46:56 17.6.2015] dir:user was nwp@1163994
<h2>
日志条目解析
</h2>
<p>
再次提下日志的格式：
</p>
<pre># XXX:[HH:MM:SS D.M.YYYY] command:fullname [+additional information]</pre>
<p>
解析日志时，主要提取下面几部分信息<br /> record_type：类型，见上述表格<br /> record_date：日期<br /> record_time：时间<br /> record_command：命令，见前一小节的分析<br /> record_fullname：一般都是节点路径名<br /> record_additional：附件信息，与 record_command 有关<br /> 从上一节的分析中可以看出，每个种类的 command 都有相似的格式，所以按照 command 采取不同的解析方法。<br /> 因为结构比较单一，所以解析时主要查找“:”和“ ”等分隔符。具体解析函数请查看源代码文件，不再列出。
</p>