SMS日志分析开发笔记01 —— 日志解析

日志文件位置

SMS 以文件形式保存日志，默认路径在 %SMSHOME%/%SMSLOG%，可以使用环境变量 SMSLOG 在 SMS 启动前设置日志文件的位置和名称。下面是我们一个 SMS 服务的变量

所以 SMS 日志就保存在在 /cma/u/nwp/smsworks/sms/cma20n03.check 文件中。该文件的内容如下：

cma20n03:/cma/u/nwp/smsworks/sms $ head cma20n03.sms.log
# MSG:[07:55:23 28.9.2015] sms:EOF in stdin, removing keyboard access
# WAR:[07:55:23 28.9.2015] checkpoint:nothing defined, ignored
# MSG:[07:55:33 28.9.2015] login:User nwp@1 with password from cma20n03
# ERR:[07:55:33 28.9.2015] SMS-NODE-READ:read error in the header
# ERR:[07:55:33 28.9.2015] SMS-NODE-READ:Read failed for cma20n03.check
# ERR:[07:55:33 28.9.2015] recover:cma20n03.check:file read failed:
# ERR:[07:55:33 28.9.2015] recover:user was nwp@1
# MSG:[07:55:33 28.9.2015] check:method time interval 120 sec by nwp@1
# MSG:[07:55:34 28.9.2015] logout:User nwp@1
# MSG:[07:55:48 28.9.2015] login:User nwp@2 with password from cma20n03

如果 SMS 运行时日志文件存在，则继续追加到该文件，否则，SMS 会自动创建日志文件。

日志内容

日志文件包含 SMS 服务器的所有动作，并显示诸如用户登录时间等信息。
它是一个纯文本文件，可以很方便地被其他程序处理。例如，XCDP 使用该文件显示 timeline 窗口。
日志文件的格式非常简单。SMS 中的每个动作都会生成一行。格式如下：

# XXX:[HH:MM:SS D.M.YYYY] command:fullname [+additional information]

其中，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>
  因为日志中的每条记录都以&#8217;# &#8216;开头，所以下面示例中将其省略。
</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>

关于 perillaroc

程序员 @ CEMC/CMA