注册 登录  
 加关注
   显示下一条  |  关闭
温馨提示!由于新浪微博认证机制调整,您的新浪微博帐号绑定已过期,请重新绑定!立即重新绑定新浪微博》  |  关闭

Tsecer的回音岛

Tsecer的博客

 
 
 

日志

 
 

超时引起的一个偶见问题  

2014-04-29 19:51:00|  分类: 脚本语言 |  标签: |举报 |字号 订阅

  下载LOFTER 我的照片书  |
现象:
现象是从一台主机(开发机)上使用脚本在一批远程主机(工作机)上执行一个shell命令,命令的内容是从大量日志中搜索出一些特定信息,其中每台主机上日志的数量比较大。
执行的时候就发现一个问题:远程执行命令时,无法在开发机上看到命令的有效输出;但是远程登录到工作机之后在终端中直接执行命令,可以搜索到有效输出。
可能的原因:
1、系统的性能监控工具或者时OOM Killer异常结束了该进程。查看系统日志/var/log/messages,没有发现oom日志。
2、grep命令的输出缓冲。
由于grep对于输出会进行缓冲,所以担心可能是由于grep的行缓冲导致的,通过grep的--help可以知道,禁止缓冲的方法是使用
      --line-buffered       flush output on every line
添加之后,没有效果。
3、ssh的输出超时。在网上搜了几个,没在主机上找到对应的配置项,作罢。
4、bash本身超时。这个从bash的手册可以知道,它通常只是在read内置函数调用时生效。
5、工具expect的超时。由于使用的脚本工具经过了基层封装,不是一眼就可以看出来的,这个是最后被怀疑到的。在后来有时间的时候,我还是看了下这个(一批)脚本,可以看到这个超时时间设置在了expect的脚本中。命令非常简单,就是在expect中的
set timeout 30
命令设置。这个超时的意义在于如果远程socket在这个时间内没有事件发生(可读事件,对应的就是远程执行命令的输出),此时expect会关闭掉该连接。
问题的验证:
在远程机器的系统日志中可以看到输出内容:
Apr 29 17:50:03 …… sshd[5002]: connection lost: 'Connection closed by remote host.'
Apr 29 17:50:21 …… sshd[18916]: connection from "172.27.128.34"
Apr 29 17:50:21 …… sshd[5051]: User root, coming from 172.27.128.34, authenticated.
Apr 29 17:50:22 …… sshd2[5054]: Now running on root's privileges.
Apr 29 17:50:23 …… sshd[5051]: Local disconnected: Connection closed.
可以看到的是
Apr 29 17:50:03 …… sshd[5002]: connection lost: 'Connection closed by remote host.'
Apr 29 17:50:23 …… sshd[5051]: Local disconnected: Connection closed.
之间相差了30秒钟,和expect中设置的时间相温和。
问题的偶见性:
这种情况需要根据远程主机的日志数量,有效记录在日志中的位置,远程主机当前负载情况等有不同的表现,同一条命令在不同时间执行可能还有不同的现象,所以看起来比较诡异,但是关键问题就是看日志,然后看超时时间。
定位的阶段:
1、在本地执行命令,同时登录到远程机器,通过ps aux查看派生的本地命令,通过/proc/$PID/cmdlines看文件名展开是否符合预期。
2、查看远程主机系统日志。首先从系统日志中看系统的异常,当时只是看到ssh的打开和关闭日期。
3、定位超时设置位置。这个需要排除可能经过的每个工具。
  评论这张
 
阅读(185)| 评论(0)
推荐 转载

历史上的今天

评论

<#--最新日志,群博日志--> <#--推荐日志--> <#--引用记录--> <#--博主推荐--> <#--随机阅读--> <#--首页推荐--> <#--历史上的今天--> <#--被推荐日志--> <#--上一篇,下一篇--> <#-- 热度 --> <#-- 网易新闻广告 --> <#--右边模块结构--> <#--评论模块结构--> <#--引用模块结构--> <#--博主发起的投票-->
 
 
 
 
 
 
 
 
 
 
 
 
 
 

页脚

网易公司版权所有 ©1997-2017