显示标签为“log”的博文。显示所有博文
显示标签为“log”的博文。显示所有博文

2012年3月29日星期四

几个简单常用的Linux命令——日志分析篇


同事说能否分享一下linux日志分析的心得,尽管我也只是初学小菜,不过既然问到了,那就献丑了。

linux里面有那么几个常用的命令,在大部分日志分析场景里面都会用到:

cut  按照特定分割符分成若干列,取出其中的某一列。
     -d" " 表示用空格作为分割符默认好像是逗号;
     -f8   表示取出第8列。

sort 按照特定的分隔符分成若干列,按照某一列进行排序。
     -d" " 表示用空格(默认应该就是空格),-f1,2表示用第1、2列输出;
     -g    表示按照数字进行排序;
     -r    表示逆序;(默认从小到大);
     -k8   表示根据第8个字段进行排序;(默认只根据第1列排序,可以通过设置IFS来指定分隔符)
     -k1,3 表示根据第1至3个字段之间的内容进行排序;
     -u    表示相同的元素只输出一次。

uniq 如果下一行重复则消除。
     -c    表示统计出现次数(重复一次计数为2)。

head 输出最开始的几行。
     -n8   表示输出头8行。(无参数时默认10行)

tail 输出最末尾的几行。
     -n8   表示输出尾8行。(无参数时默认10行)

wc   输出指定文字出现的次数。
     -l    表示输出出现该文字的行数而不是次数。

grep 输出包含指定文字的若干行。
     -i    表示大小写不敏感;
     -e    表示使用正则表达式;(等同于egrep命令)
     -v    表示输出不等于制定文字的若干行;
     -m8   表示指定文件中的输出前8个;
     -a    表示如果是二进制文件,则仅对比里面是文字的部分;(比如要找squid缓存文件当中记录的,与该文件对应的uri时就特别有用);
     -r    表示递归搜索所有文件夹中的指定文件;
     -H    在每一行输出中均包括文件名;(搜索单个文件时默认不输出)
     -h    在每一行输出中均不包含文件名;(搜索多个文件时默认输出)
     -l    仅输出有命中的文件名;
     -L    仅输出没有命中的文件名;
     -B8   输出命中该行之前的8行;
     -A8   输出命中该行之后的8行;
     -c    仅输出命中次数。

上面这个命令组合通常就可以进行大部分的日志分析工作,下面举例说明。

我们假设日志名称为squid.log,格式如下所示(有点像Squid,但实际上不是真实的日志格式,只是为了便于说明):
- - [2012/1/1 04:23:44] 223.33.54.123 "GET /pages/head.htm HTTP/1.1" {www.fix.com|http://www.google.com/search} 200 - - TCP_HIT:NONE "Mozilla/4.0"

例1 查看最后若干个访问"/pages/head.htm"的IP都来自哪里:
grep -i "/pages/head.htm" squid.log | tail -n20 | cut -d" " -f5
注意:

  1. 日期和时间当中有一个空格,因此是两个字段,而不会因为方括号而认为是一个字段。同样的,单引号双引号也不会影响以空格为分割符的分割;
  2. 如果文件非常大导致明显非常慢,可以尝试用tail作为开头进一步限制,如:

tail -n1000 squid.log | grep -i "/pages/head.htm" | tail -n20 | cut -d" " -f5



例2 统计最后若干个访问"/pages/head.htm"的IP的次数:
grep -i "/pages/head.htm" squid.log | tail -n1000 | cut -d" " -f5 | sort | uniq -c | sort -g
备注:这里的技巧是,先要sort,然后再通过uniq -c来统计次数,然后再通过sort来进行排序。这是因为对于uniq命令来说,之比较上一行和下一行,而不会考虑交错的情况,例如对于文件tmp如下:
A
A
B
B
A
A
C

用uniq -c tmp来检查,输出如下:
2 A
2 B
2 A
1 C

而实际上我们希望的输出类似如下:
1 B
2 C
4 A

于是只能够通过sort先将相同的内容放到一起,然后再用uniq来统计。sort命令当中的-u参数并不会统计处数量,于是必须使用uniq命令。同时uniq输出的顺序是原始文本出现的顺序,而不是根据数量进行排序的,因此最后还需要用sort进行排序。


例3 统计最后若干个访问"/pages/head.htm"的IP中,出现次数最多的前三名以及其次数:
grep -i "/pages/head.htm" squid.log | tail -n1000 | cut -d" " -f5 | sort | uniq -c | sort -gr | head -n3



例4 统计后端返回状态为503的访问次数:
cut -d" " -f10 "/pages/head.htm" squid.log | grep 503 | wc -l


例5 统计后端返回状态为200,且访问"/pages/head.htm"的HIT和MISS的情况(日志中TCP_HIT:NONE的那一列)
这一个需求比较复杂,我们需要动用上面没有介绍到的另一个命令:awk

awk  对每一行按照指定分隔符进行分割,并根据指定的条件输出指定的内容。
     -F" " 表示输出以空格作为分割符。

完整命令格式如下:

awk [条件] ['指令'] [待分析文件]
之所以指令是可选的,是因为参数中还有一个可以指定指令文件的参数;而待分析文件可选,是因为可以通过管道提供待分析文件。

其中的指令部分比较复杂,完整的这里就不介绍了,请自行谷歌之。这里介绍非常简单的几个常用部分。
$1       表示第一个字段
$1>2     表示第一个字段是数字且大于数字2
$1>"2"   表示第一个字段大于字符2,也就是说"12"<"2"
$1==$2   表示第一个字段等于第二个字段
&&       表示与
||       表示或
a { b }  表示如果前面的a部分匹配,则执行b部分
print    表示输出整行
print $1 表示输出第一个字段
;        表示两个指令之间的分割

于是
$1==200 { print; }
就是说第一列等于200就输出整行。

对于本示例,将需要使用如下命令:
awk -F" " '$10==200 { print; }' squid.log | grep -i "/pages/head.htm" | cut -d" " -f13 | sort | uniq -c | sort -g


例5 统计UserAgent的情况,但前面的访问路径处可能包含不定数量的空格,比如某些访问没有发出HTTP/1.1,于是只有"GET /pages/head.htm"。


这个问题很容易想到:啊,如果能够忽略双引号中的空格多好啊!嗯,这种思路应该也是可以的,但是比起下面这种思路来说,有的时候真的太复杂了。
cut -d\" -f4 squid.log | sort | uniq -c | sort -g

“……靠,还能用双引号做分割符,咋就没想到呢?”好吧,再提示一下:每一个命令可以考虑使用不同的分割符,而不需要每一次都用同一个分割符。

2012年3月13日星期二

初学配置安装Linux撞鬼集3 - 莫名其妙的squid

知道为什么Linux的维护/开发人员值钱吗?因为Linux世界真的有太多不可思议的事情了:比如说相对于可以调整的参数及其导致的莫名其妙的问题,文档和记录实在是太少了。这里就拿squid来说说吧。

我们使用的Squid服务器之前跑得好好的,突然有一天出现了严重的问题:磁盘空间满了,上去一查,发现在/app/squid/var/logs这个目录里面全是core.12345这样的dump文件,而且几乎是每秒钟都要产生这样的dump。通过gdb打开之后发现,几乎每一个dump都出现了类似如下的情况:

Core was generated by `(squid)'.
Program terminated with signal 6, Aborted.
#0 0x000000373aa30265 in raise () from /lib64/libc.so.6
(gdb) where
#0 0x000000373aa30265 in raise () from /lib64/libc.so.6
#1 0x000000373aa31d10 in abort () from /lib64/libc.so.6
#2 0x00000000004812d1 in fatal_dump ()
#3 0x000000000049c7f9 in xcalloc ()
#4 0x000000000047cc8b in storeKeyDup ()
#5 0x0000000000475b4a in storeHashInsert ()
#6 0x000000000048f280 in storeAufsDirAddDiskRestore ()
#7 0x000000000049092e in storeAufsDirRebuildFromSwapLog ()
#8 0x00000000004375d4 in eventRun ()
#9 0x000000000045da06 in main ()

上面标黄的#3这一行就是问题所在,在其下面的堆栈情况则并不一定。如果你直接搜索xcalloc和squid,几乎是找不到任何线索的。当然,你仔细看网上那些英文帖子的话呢,也会看到有人提示你使用free看看内存是否充足,使用df看看磁盘是否满了。可是你一看,就会发现其实很正常。在Google上搜索这两个关键词,几乎都会指向这样一个Bug,这里面的堆栈和我遇到的问题极度相似。可问题是,人家使用的是3.1系列,而我使用的是2.7系列。而这个BUG的讨论中有人说了,3.1有问题但2.7没有。而且该Bug的描述说的是,如果有人POST了一个很大的文件,超出了内存容量,则可能会出现此错误。但显然,因为这种问题导致频繁当机的可能性太低了,不应该是这个原因。到了这里,似乎又没有任何头绪了。

实际上,如果仔细看第一个帖子,里面还有人贴出了大量的信息,什么Dependencies.txt、Disassembly.txt啊等等。关键的地方其实都不在这些链接里面,而是5楼的回复
I'm seeing this too; I'm attaching the /var/log/squid-deb-proxy/cache.log, which seems to indicate that squid is attempting to allocate approximately 10PB of memory for swap. This, obviously, fails; hence the abort. 
也就是说,在这个cache.log里面会有线索。Linux先进的地方就在于日志真的很多,dump也很多。但问题也很多,尤其是莫名其妙的问题。那么在这个日志文件里面又说了什么呢?在我这里,这个日志大致如下:
FATAL: xcalloc: Unable to allocate 1 blocks of 4112 bytes!
Squid Cache (Version 2.7.STABLE9): Terminated abnormally.
CPU Usage: 23.655 seconds = 11.627 user + 12.028 sys
Maximum Resident Size: 4665232 KB
Page faults with physical i/o: 0
Memory usage for squid via mallinfo():
        total space in arena:  1020340 KB
        Ordinary blocks:       1020328 KB     38 blks
        Small blocks:               0 KB      0 blks
        Holding blocks:        166348 KB      8 blks
        Free Small blocks:          0 KB
        Free Ordinary blocks:      11 KB
        Total in use:          1186676 KB 100%
显然,我这里的情况和BUG所导致的症状很不一样。前者每次都是分配一个很小的内存——最低只有24字节,最大也不过几KB;而后者则是分配4035364077 blocks of 1 bytes。这就进一步增加了此问题非彼问题的几率了,可还是不知道问题在哪对不?好在这次又有了另一个新的关键词:FATAL: xcalloc: Unable to allocate 1 blocks of bytes

这个问题一搜索,就发现有不少人报告这个问题,除了上面提到的BUG之外,也有像我这种分配一点点内存即报错的(B贴)。当然,也有中文贴,只不过中文贴貌似真没几个人进来讨论,就更不要抱给点营养的希望了。

除了报Bug之外,还有一些文档说这个问题“通常”跟以下两个问题有关:
  1. 这个机器的磁盘交换空间用完了;或者
  2. 这个进程的数据段大小已经达到最大限制了。
对于这两个问题,第一个应该用ps -m或者cat /proc/mem查看。(如果你想知道具体交换文件在哪里,可以用cat /proc/swaps或者swapon -s来查看,坑太多了,这里插播一下。)第二个问题可以通过ulimit -a和ulimit -aH来查看,其中第一个似乎是查看目前的配置,第二个似乎是硬件本身以及kernel编译时的限制。

我执行第一个命令之后,发现空余的交换空间足以将整个进程都交换进去,而正在使用的交换空间则小得可怜(也就100兆),于是第一个问题可以排除。而第二个命令则发现data seg size均设置为unlimited,这个问题也可以排除了。于是这个文档又没有解决问题。

(插播一下,你需要通过运行uname -a来看看你的系统是否64位。如果是32位的系统,也可能会有2G左右的内存大小的限制。)

最后,还是B贴的最后一个说法给出了本问题的终极答案:编译时去掉dlmalloc参数就能解决问题了。而且在这里,你还得到了另一个“有用的”忠告:不要使用你不知道你是否需要的配置参数。这真是一个有用的忠告啊!后面再说这个问题。

真TMD神奇了,这可是从repo下载下来的源代码的默认编译参数啊!那么dlmalloc又是一个什么玩意儿呢?上面那个讨论中说道:
这个参数是为了让那些malloc内存分配函数实现得很糟糕的操作系统所准备的。要知道你是否正好走了这种狗屎运,(在关掉这个参数的情况下,编者注)你会看到Squid不停的增长,但已分配的内存没有变化,而空余内存则一直在增长。
我估计说的是内存地址空间增加,但实际分配的数量很少。相应的,因为内存地址增加导致总虚拟内存增加,而空余内存则因为总虚拟内存-实际分配内存的计算,导致空余内存不停增加的假象。

如果你想知道具体什么是dlmalloc,这篇文章会告诉你这是一个叫做Doug Lea的同志,在1987开始写的内存分配函数。由于该邮件是1996年从德语翻译过来的,所以估计在那时候已经基本稳定了。换句话说,这是一个古董。而这个古董级的文件可能根本就无法分配超过2G的内存,甚至在前面那个B贴中说无法超过1G,而我的实际情况也是似乎无法超过1.2G。可是这个问题在很多地方都没有提及,尤其是中文的编译参数详解说明

看到了吧,Linux里面可以动的东西很多,坑也就很多。大家一定要注意了,LINUX下面的默认编译安装方式,有可能会要了你的亲命。为了避免出现像我这里描述的问题,去掉默认参数也许都不是稳妥的。因为有可能某些参数一去掉,这种隐藏的Bug是没有了,但性能就急剧下降,甚至你无法证明你的系统必须要有某些参数才能够工作。于是,保险的办法应该是了解都有哪些编译参数,每一个参数是干什么的,你的系统有什么限制,你需要什么样的优化。这才是刚才那句忠告的终极含义!

换句话说,你需要搞清楚什么事内存分配,malloc和dlmalloc的关系,还要英语过硬知道怎么搜索。这,就是一个linux系统应用维护人员所需要具备的基本素质,可不是Windows人员拷贝安装就可以搞定的。这还不包含安装完毕之后的各种配置呢!




2012年3月5日星期一

初学配置安装Linux撞鬼集

对于刚踏入Linux的同学,肯定会遇到不少“撞鬼”的事情。所谓撞鬼,就是说:“邪门了,怎么就是不行呢?”为了让大家不要重蹈覆辙,这里记录一些我遇到过的事情。

为什么不能往特定目录记录日志?

这个问题的来由是这样的:某天我需要在内网一台已经配置好的Linux服务器上面,配置一整套与线上正式环境完全相同的测试环境。其中有一个步骤就是安装HAProxy,安装的过程基本还算顺利。配置并运行后发现,服务倒是起来了,但日志却没有记录到指定的文件当中。

需要说明的是,HAProxy这里选用了syslogd的方式,在/etc/sysconfig/syslog里面开了-r -x参数,然后在 /etc/syslog.conf 里面添加了一行“local3.* /mydir/logs/haproxy.conf”,同时修改好haproxy的配置"log 127.0.0.1 local3 info"。本以为这么配置一下就大吉了,但是实际上却发现该目录下面没有该日志文件,这就诡异了。由于一开始配置错误,选择了local7,于是日志记录到了/var/log/boot.log里面去了。所以很明显,该问题不是因为HAProxy或者syslogd配置错误导致。通过使用ls -l以及getfacl来查看各个目录和文件的情况,发现测试环境和正式环境是完全一致的。那么,到底撞什么鬼了?

经过一番查找,发现了这么一篇FAQ,发现原来:

  • /etc/syslog.conf的配置里面不应该使用空格而是"tab",来区分前面的local3.*和后面的目录;
  • syslogd不会自己创建文件,要你自己先创建文件(比如用touch /mydir/logs/haproxy.log)。

我第一个念头就是“真狗屎”,你说这叫什么事啊,tab才行空格就不行,还要自行先创建文件。好吧,为了安全,还是自己动手丰衣足食好一点。由于凑巧使用的是tab而不是空格,第一个问题我没有遇到。而第二个问题,我确实没有创建该文件,只好老老实实touch了一下。可是touch完了,这个文件中还是没有任何的日志,哪怕我狂刷浏览器。这就奇了怪了!

经过咨询周围了解linux的同学,还有当初架设线上服务器的前同学,最后终于发现……他们也不知道为什么。非常沮丧的我只好“胡乱瞎试”:

  • 既然我自己创建的目录里面不能记录日志,但是/var/log可以记录,那肯定是这两个目录的某种差异,甚至最可能的就是权限差异造成的;
  • 既然/var/log可以记录,那肯定可以在这个目录当中创建新的log;
  • 既然可以配置,那干脆把所有日志都记到某个文件当中好了。

于是配置/etc/syslog.conf,添加一行“*.* /var/log/debug2.log”,并touch之,然后service syslog restart。这时候通过more /var/log/debug2.log就会发现,里面有那么一行:
某年某月的某一天 时分秒 机器名字 setroubleshoot: SELinux 正在阻止访问带有默认标签 default_t 的文件。 For complete SELinux messages. run sealert -l 某个GUID

好吧,我手贱,语言选了中文,懒得改回去了。英文版本的应该是“…… SELinux is preventing access to files with the default label, default_t. ……”。

上述信息的含义,是安全上下文环境设置不正确导致的,通过使用命令 ls -Z /mydir/logs可以看到该目录下面的上下文设置信息,如下所示:
-rw-r--r--  root root root_u:object_r:default_t      haproxy.log

根据某处搜索的结果,发现setfattr -x security.selinux可以解决这个问题,很是高兴。但结果一运行,就会告知“没有足够的权限”。NND,我可是用的root啊!经询问才发现,原来是开启了SELinux的缘故。于是有人提供了另一个方案,就是使用setup将selinux给禁用了。

禁用这个方法肯定可以,但显然不是最好的办法。所谓SELinux,就是为了提高系统安全性的东西。禁止它,一定是比较糟糕的实施方式。那应该怎么办呢?

嗯,很简单,参照/var/log这个目录,及其内部文件的响应设置即可(使用命令ls -Z查看)。具体一点,就是执行:
chcon -u system_u -t var_log_t 文件或目录路径
或者
chcon -u system_u -t var_log_t -R 目录路径

其中后者会将该目录下所有的子目录和文件都设置成相同的安全参数,经过这样的设置,日志的记录就成功了。

总结:

  • 配置啥的都对了,也有可能因为各种安全性的原因而无法正常运行;
  • 由于Linux的设计思路是“没有错误”就不输出,但实际上有些时候因为配置的问题,一些错误信息也是不输出的,导致你总觉得正常,但偏偏就不正常。此时一定要想办法让其尽可能输出详细的信息,例如将所有系统/应用的日志都输出到某个日志文件当中。

(待续)