主机管理+堡垒机系统开发：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
", 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, "000237h
^203203210363233250T:243314303212a\214264274q332314347hv&"..., 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, "20256365;234241327376A265M!311257p304257343012623762222312411774(353347"..., 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, "20177jU316211!5256305F2364g16317237302234333D337v3653020W311|"..., 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, "20203372262354\263322$2422666`34727127254224261i325021233R371""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, "20R260XK253233331321223265w275335366	277f3574v:227276360s336K"..., 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, "20303c231;23324272733126027733350@2503n344vT241351276347x304363233"..., 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, "000237h
^203203210363233250T:243314303212a\214264274q332314347hv&"..., 84) = 84
[root@elk ~]# cat trace.log |grep 'read(3'
24444 16:48:11 read(3, "20256365;234241327376A265M!311257p304257343012623762222312411774(353347"..., 16384) = 52
24444 16:49:12 read(3, "20177jU316211!5256305F2364g16317237302234333D337v3653020W311|"..., 16384) = 52
24444 16:50:12 read(3, "20203372262354\263322$2422666`34727127254224261i325021233R371""242"..., 16384) = 52
24444 16:51:12 read(3, "20R260XK253233331321223265w275335366	277f3574v:227276360s336K"..., 16384) = 52
24444 16:51:53 read(3, "20303c231;23324272733126027733350@2503n344vT241351276347x304363233"..., 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("33[031;1mSession log record err,please contact your IT admin,33[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 = '审计日志'