主机管理+堡垒机系统开发：strace命令及日志解析（五）
一、strace命令简介
测试命令截图
第一个窗口执行命令如下
[root@elk ~]# w 16:51:56 up 3 days, 6:01, 3 users, load average: 0.04, 0.07, 0.11 USER TTY FROM LOGIN@ IDLE JCPU PCPU WHAT root pts/0 192.168.118.83 10:38 6:09m 0.05s 0.05s -bash root pts/1 192.168.118.30 11:45 4.00s 0.11s 0.10s -bash root pts/2 192.168.118.30 16:41 3:24 0.05s 0.05s -bash [root@elk ~]# ps -ef|grep ssh root 875 1 0 8月10 ? 00:00:00 /usr/sbin/sshd -D root 7191 875 0 16:41 ? 00:00:00 sshd: root@pts/2 root 7507 24446 0 16:47 pts/1 00:00:00 grep --color=auto ssh root 20957 875 0 10:38 ? 00:00:00 sshd: root@pts/0 root 24444 875 0 11:45 ? 00:00:00 sshd: root@pts/1 [root@elk ~]# strace -f -p 24444 -t -o trace.log strace: Process 24444 attached
第二个窗口操作
[root@elk conf]# cd
[root@elk ~]# ll
总用量 8
-rw-------. 1 root root 1002 8月 2 17:18 anaconda-ks.cfg
-rw-r--r-- 1 root root 842 8月 13 16:47 trace.log
[root@elk ~]# netstat -lntup
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
tcp 0 0 0.0.0.0:22 0.0.0.0:* LISTEN 875/sshd
tcp6 0 0 :::4002 :::* LISTEN 14808/java
tcp6 0 0 :::4102 :::* LISTEN 14808/java
tcp6 0 0 :::9200 :::* LISTEN 5207/java
tcp6 0 0 :::9300 :::* LISTEN 5207/java
tcp6 0 0 :::22 :::* LISTEN 875/sshd
tcp6 0 0 :::8090 :::* LISTEN 14808/java
udp 0 0 0.0.0.0:68 0.0.0.0:* 819/dhclient
[root@elk ~]# top
top - 16:47:37 up 3 days, 5:57, 3 users, load average: 0.06, 0.08, 0.12
Tasks: 101 total, 2 running, 99 sleeping, 0 stopped, 0 zombie
%Cpu(s): 5.9 us, 5.9 sy, 0.0 ni, 88.2 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 18136232 total, 14974344 free, 1835300 used, 1326588 buff/cache
KiB Swap: 8388604 total, 8388604 free, 0 used. 15926016 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1 root 20 0 51616 3760 2568 S 0.0 0.0 1:01.66 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.06 kthreadd
3 root 20 0 0 0 0 S 0.0 0.0 0:02.01 ksoftirqd/0
5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
7 root rt 0 0 0 0 S 0.0 0.0 0:00.00 migration/0
8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh
9 root 20 0 0 0 0 S 0.0 0.0 0:17.93 rcu_sched
10 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 lru-add-drain
11 root rt 0 0 0 0 S 0.0 0.0 0:02.32 watchdog/0
[root@elk ~]# ll
总用量 8
-rw-------. 1 root root 1002 8月 2 17:18 anaconda-ks.cfg
-rw-r--r-- 1 root root 842 8月 13 16:47 trace.log
[root@elk ~]# cd /usr/local/
[root@elk local]# ll
总用量 4
drwxr-xr-x. 2 root root 6 4月 11 12:59 bin
drwxr-xr-x 15 root root 154 8月 13 11:53 ccb-client
drwxr-xr-x. 2 root root 6 4月 11 12:59 etc
drwxr-xr-x. 2 root root 6 4月 11 12:59 games
drwxr-xr-x. 2 root root 6 4月 11 12:59 include
drwxr-xr-x 8 10 143 4096 3月 21 2016 jdk1.8.0_77
drwxr-xr-x. 2 root root 6 4月 11 12:59 lib
drwxr-xr-x. 2 root root 6 4月 11 12:59 lib64
drwxr-xr-x. 2 root root 6 4月 11 12:59 libexec
drwxr-xr-x. 2 root root 6 4月 11 12:59 sbin
drwxr-xr-x. 5 root root 46 4月 11 12:59 share
drwxr-xr-x. 2 root root 51 8月 2 17:28 src
[root@elk local]# cd ..
[root@elk usr]# vim /etc/hosts
日志跟踪文件trace.log
[root@elk ~]# cat trace.log
24444 16:47:21 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
24444 16:47:21 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
24444 16:47:21 clock_gettime(CLOCK_BOOTTIME, {280620, 614943888}) = 0
24444 16:47:21 read(12, "strace: Process 24444 attached\r\n", 16384) = 32
24444 16:47:21 clock_gettime(CLOCK_BOOTTIME, {280620, 615243828}) = 0
24444 16:47:21 select(13, [3 5 12], [3], NULL, NULL) = 1 (out [3])
24444 16:47:21 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
24444 16:47:21 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
24444 16:47:21 clock_gettime(CLOCK_BOOTTIME, {280620, 615599914}) = 0
24444 16:47:21 write(3, "\0\0\0000\237h\n^\203\203\210\363\233\250T:\243\314\303\212a\\\214\264\274q\332\314\347h\v&"..., 84) = 84
24444 16:47:21 clock_gettime(CLOCK_BOOTTIME, {280620, 615804167}) = 0
24444 16:47:21 select(13, [3 5 12], [], NULL, NULL) = 1 (in [3])
24444 16:48:11 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
24444 16:48:11 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
24444 16:48:11 clock_gettime(CLOCK_BOOTTIME, {280671, 239232964}) = 0
24444 16:48:11 read(3, "\0\0\0\20\256\365;\234\241\327\376A\265M!\311\257p\304\257\34\301\262\376\222\231\241\1774(\353\347"..., 16384) = 52
24444 16:48:11 clock_gettime(CLOCK_BOOTTIME, {280671, 239559322}) = 0
24444 16:48:11 select(13, [3 5 12], [], NULL, NULL) = 1 (in [3])
24444 16:49:12 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
24444 16:49:12 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
24444 16:49:12 clock_gettime(CLOCK_BOOTTIME, {280731, 254936108}) = 0
24444 16:49:12 read(3, "\0\0\0\20\177jU\316\211!5\256\305F\236\4g\16\317\237\302\234\333D\337v\365\3020W\311|"..., 16384) = 52
24444 16:49:12 clock_gettime(CLOCK_BOOTTIME, {280731, 255319942}) = 0
24444 16:49:12 select(13, [3 5 12], [], NULL, NULL) = 1 (in [3])
24444 16:50:12 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
24444 16:50:12 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
24444 16:50:12 clock_gettime(CLOCK_BOOTTIME, {280791, 266306720}) = 0
24444 16:50:12 read(3, "\0\0\0\20\203\372\262\354\\\263\322$\242\266\6`\347\271\27\254\224\261i3\250\212\33R\371\"\"\242"..., 16384) = 52
24444 16:50:12 clock_gettime(CLOCK_BOOTTIME, {280791, 266653313}) = 0
24444 16:50:12 select(13, [3 5 12], [], NULL, NULL) = 1 (in [3])
24444 16:51:12 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
24444 16:51:12 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
24444 16:51:12 clock_gettime(CLOCK_BOOTTIME, {280851, 280884675}) = 0
24444 16:51:12 read(3, "\0\0\0\20R\260XK\253\233\3\31\321\223\265w\275\335\366\t\277\f\3574\v:\227\276\360s\336K"..., 16384) = 52
24444 16:51:12 clock_gettime(CLOCK_BOOTTIME, {280851, 281262652}) = 0
24444 16:51:12 select(13, [3 5 12], [], NULL, NULL) = 1 (in [3])
24444 16:51:53 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
24444 16:51:53 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
24444 16:51:53 clock_gettime(CLOCK_BOOTTIME, {280892, 379224898}) = 0
24444 16:51:53 read(3, "\0\0\0\20\303c\231;\233\2427\273\31\260\277\33\350@\250\3n\344vT\241\351\276\347x\304\363\233"..., 16384) = 52
24444 16:51:53 clock_gettime(CLOCK_BOOTTIME, {280892, 379519032}) = 0
24444 16:51:53 select(13, [3 5 12], [8], NULL, NULL) = 1 (out [8])
24444 16:51:53 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
24444 16:51:53 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
24444 16:51:53 clock_gettime(CLOCK_BOOTTIME, {280892, 379862413}) = 0
24444 16:51:53 write(8, "\3", 1 <detached ...>
过滤后的是都是什么东东呀？
[root@elk ~]# cat trace.log |grep 'write(3' 24444 16:47:21 write(3, "\0\0\0000\237h\n^\203\203\210\363\233\250T:\243\314\303\212a\\\214\264\274q\332\314\347h\v&"..., 84) = 84 [root@elk ~]# cat trace.log |grep 'read(3' 24444 16:48:11 read(3, "\0\0\0\20\256\365;\234\241\327\376A\265M!\311\257p\304\257\34\301\262\376\222\231\241\1774(\353\347"..., 16384) = 52 24444 16:49:12 read(3, "\0\0\0\20\177jU\316\211!5\256\305F\236\4g\16\317\237\302\234\333D\337v\365\3020W\311|"..., 16384) = 52 24444 16:50:12 read(3, "\0\0\0\20\203\372\262\354\\\263\322$\242\266\6`\347\271\27\254\224\261i3\250\212\33R\371\"\"\242"..., 16384) = 52 24444 16:51:12 read(3, "\0\0\0\20R\260XK\253\233\3\31\321\223\265w\275\335\366\t\277\f\3574\v:\227\276\360s\336K"..., 16384) = 52 24444 16:51:53 read(3, "\0\0\0\20\303c\231;\233\2427\273\31\260\277\33\350@\250\3n\344vT\241\351\276\347x\304\363\233"..., 16384) = 52
二、目录结构
三、实现代码
1、日志解析
import re
class AuditLogHandler(object):
'''分析audit log日志'''
def __init__(self,log_file):
self.log_file_obj = self._get_file(log_file)
def _get_file(self,log_file):
return open(log_file)
def parse(self):
cmd_list = []
cmd_str = ''
catch_write5_flag = False #for tab complication
for line in self.log_file_obj:
#print(line.split())
line = line.split()
try:
pid,time_clock,io_call,char = line[0:4]
if io_call.startswith('read(4'):
if char == '"\\177",':#回退
char = '[1<-del]'
if char == '"\\33OB",': #vim中下箭头
char = '[down 1]'
if char == '"\\33OA",': #vim中下箭头
char = '[up 1]'
if char == '"\\33OC",': #vim中右移
char = '[->1]'
if char == '"\\33OD",': #vim中左移
char = '[1<-]'
if char == '"\33[2;2R",': #进入vim模式
continue
if char == '"\\33[>1;95;0c",': # 进入vim模式
char = '[----enter vim mode-----]'
if char == '"\\33[A",': #命令行向上箭头
char = '[up 1]'
catch_write5_flag = True #取到向上按键拿到的历史命令
if char == '"\\33[B",': # 命令行向上箭头
char = '[down 1]'
catch_write5_flag = True # 取到向下按键拿到的历史命令
if char == '"\\33[C",': # 命令行向右移动1位
char = '[->1]'
if char == '"\\33[D",': # 命令行向左移动1位
char = '[1<-]'
cmd_str += char.strip('"",')
if char == '"\\t",':
catch_write5_flag = True
continue
if char == '"\\r",':
cmd_list.append([time_clock,cmd_str])
cmd_str = '' # 重置
if char == '"':#space
cmd_str += ' '
if catch_write5_flag: #to catch tab completion
if io_call.startswith('write(5'):
if io_call == '"\7",': #空键，不是空格，是回退不了就是这个键
pass
else:
cmd_str += char.strip('"",')
catch_write5_flag = False
except ValueError as e:
print("\033[031;1mSession log record err,please contact your IT admin,\033[0m",e)
#print(cmd_list)
# for cmd in cmd_list:
# print(cmd)
return cmd_list
if __name__ == "__main__":
parser = AuditLogHandler('tmp/ssh_log2_4')
parser.parse()
2、拿不到pid的解决方案
#!/bin/bash
ssh_tag=$1
echo "----$ssh_tag---"
for i in $(seq 1 30);do
process_id=$(ps -ef |grep $ssh_tag|grep -v sshpass |grep -v grep |grep -v $0 | awk '{ print $2 }' )
echo "---process id: $process_id ---"
if [ ! -z $process_id ];then
echo 'running str4ack'
log_path=/home/traum/CrazyEye/log/`date +%F`
mkdir -p $log_path
sudo strace -fp $process_id -t -o $log_path/session_$2.log
break;
fi;
sleep 1;
done;
3、规范日志存储
class Session(models.Model):
'''生成用户操作session id '''
user = models.ForeignKey('UserProfile')
bind_host = models.ForeignKey('BindHost')
tag = models.CharField(max_length=128,default='n/a')
closed = models.BooleanField(default=False)
cmd_count = models.IntegerField(default=0) #命令执行数量
stay_time = models.IntegerField(default=0, help_text="每次刷新自动计算停留时间",verbose_name="停留时长(seconds)")
date = models.DateTimeField(auto_now_add=True)
def __str__(self):
return '<id:%s user:%s bind_host:%s>' % (self.id,self.user.email,self.bind_host.host)
class Meta:
verbose_name = '审计日志'
verbose_name_plural = '审计日志'
作者：罗阿红
出处：http://www.cnblogs.com/luoahong/
本文版权归作者和博客园共有，欢迎转载，但未经作者同意必须保留此段声明，且在文章页面明显位置给出原文连接。
