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 时间,两者可能不同。

符号含义
MSG用户动作、常规操作生成的信息
LOGtask 或 SMS、常规操作生成的信息。最常见的消息就是节点的状态改变。
ERR错误消息,无法完成的非常规操作。某些操作在客户端被忽略,如尝试发送SMS中不存在的 label 或 event 对 SMS 端来说就是一个错误,但在客户端则不是。
WAR警告消息,不是错误但校正后的操作被执行。例如,使用旧版本客户端会产生一条警告记录。
DBG调试信息,默认不显示,必须由管理员打开。
others如果 SMS 以交互模式运行,日志中可能会记录键盘输入。处理日志的程序应该忽略这些行。
<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>