PowerShell小技巧：通过 PowerShell实现日志关键字分析

Posted 2022-05-29 微风ATBJ

场景

近期因线上业务系统的某一服务频繁出问题，厂商建议对其日志的部分关键词做监控并做到及时提示。其实针对这类简单的日志监控我个人理解，通过ELK、Splunk甚至是Zabbix这类的均能实现。但因本人对上述系统均了解皮毛，无法在短时间内完成这一需求。故本次通过 Google 以及大佬们的指点，使用相对熟悉一点的 Powershell（当然，PowerShell也一样只是了解皮毛）来实现。

---

日志文件分析

1、业务提供的需求：

• 任务每天执行两次，日志保存在指定路径的固定log文件内；
• ERROR 为错误关键词，当出现这个必须及时通知；
• SUCCESSFULLY 为任务成功，也需要给出提示；

2、分析日志文件

3、思路

通过这个规律，我的想法是先使用 Powershell 实现：

1. 快速检索并定位到日志文件中最后一次出现 ERROR 以及 SUCCESSFULLY 关键词；
2. 定位到最后一次出现 ERROR以及 SUCCESSFULLY时间的时间点以及所在日志的行数；
3. 快速检索并定位到日志文件中最后一次出现DRESYNC的信息，并筛选出Next scheduled execution time for DRESYNC后面的时间点以及该日志所在行；

当上述日志关键字以及相关信息定位到以后，可以通过以下逻辑来判断任务执行成功或失败：

• 当最后一次出现SUCCESSFULLY关键字的所在行数大于最后一次出现 ERROR 关键字的所在行数，说明该条件下上一次任务执行的状态为SUCCESSFULLY，相反则说明上一次任务执行失败；
• 为了避免例外，再加上一条：当最后一次出现SUCCESSFULLY关键字的时间大于最后一次出现 ERROR 关键字的时间，说明该条件下上一次任务执行的状态为SUCCESSFULLY，相反则说明上一次任务执行失败；
• 当最后一次出现关键词DRESYNC后面的时间小于等于当前系统时间，说明任务正在执行，相反则任务未开始；

---

代码

$Content = cat "/Users/jason/synctool.log"
$LASTERRORContent = $Content | Select-String -Pattern "ERROR" | Select-Object -Last 1 # Pattern 后面加 -Context 5,3 为匹配目标上方 5 行 & 匹配目标下方 3 行
$LASTSUCCESSContent = $Content | Select-String -Pattern "ACTIVE CONTENT ENGINE EXPORT JOB PROCESSED SUCCESSFULLY" | Select-Object -Last 1 # -Context 3, 3 
$LastScheduleContent = $Content | Select-String -Pattern "Next scheduled execution time for DRESYNC" | Select-Object -Last 1 
$CurrentTime = Get-Date
$NextRUNTimes = $Content | Select-String -Pattern "Next scheduled execution time for DRESYNC" | Select-Object -Last 1
$LSTERRN = ($LASTERRORContent).LineNumber # 最后一次 ERROR 所在行
$LSTSUCN = ($LASTSUCCESSContent).LineNumber #最后一次 SUCCESSFULLY 所在行
$LSTSCHN = ($LastScheduleContent).LineNumber #最后一次 DRESYNC 所在行
$LastErrorTime = [datetime]($LASTERRORContent -Split (,) | Select-Object -First 1)
$LastSuccessTime = [datetime]($LASTSUCCESSContent -Split (,) | Select-Object -First 1)#$NextRUNTime = ($NextRUNTimes -split "`n" | ForEach-Object  $_ -match "(DRESYNC: )(.*?)( CST)" | Out-Null; $Matches[2] ).foreach([datetime]) #获取Next Scheduled execution time时间点,并转换为时间格式
$NextRUNTime = [datetime]($NextRUNTimes -split "`n" | ForEach-Object  $_ -match "(DRESYNC: )(.*?)( CST)" | Out-Null; $Matches[2] )

if ($CurrentTime -ge $NextRUNTime) 
    <# 当前系统时间大于等于日志中最后一次出现的下一次任务执行时间时“”说明该计划任务开始执行，且并未执行完成 #>
    Write-Output "任务正在执行中。。。。。"

else 
    <# 当前系统时间小于日志中最后一次出现的下一次任务执行时间时：说明下一次计划任务还未开始。需要分析上一次任务的执行完成状态#>
    if (($LSTSUCN -gt $LSTSCHN) -and ($LastSuccessTime -gt $LastErrorTime) -and ($LastSuccessTime -lt $NextRUNTime)) 
        <# 如果最后一次出现下一次计划执行DRESYNC时间之后是 SUCCESSFULLY；且最后一次出现 SUCCESSFULLY 的时间大于最后一次出现 ERROR 的时间，说明上一次任务执行成功 #>
        Write-Output $LASTSUCCESSContent 
    
    elseif (($LSTERRN -gt $LSTSCHN) -and ($LastErrorTime -gt $LastSuccessTime) -and ($LastErrorTime -lt $NextRUNTime)) 
        <# 如果最后一次出现下一次计划执行DRESYNC时间之后是ERROR；且最后一次出现 SUCCESSFULLY 的时间小于最后一次出现 ERROR 的时间，说明上一次任务执行失败 #>
        Write-Output $LASTERRORContent
    

手动修改日志的内容，确认条件判断无误

---

应用

脚本写完后面就是考虑到如何去应用了。我常用的有 2 种方法，这里我只提供下思路，后期有时间再去更新如何去实现:

1. 通过 Windows 计划任务执行该脚本，并在脚本中增加触发条件发送至企业微信机器人；
2. 通过 Zabbix 自定义脚本，将固定的输出传入 Zabbix ，然后通过监控项、触发器去针对指定上述脚本输出的结果去做需要的告警发送邮件或者企业微信机器人；

---

特别鸣谢： 九叔、彪哥、Summpot 三位大佬的热心帮助（排名不分先后）