某日接到客户反馈,某系统备机重启后 telnet 无法登录,提示信息如下:
telnet (testlpar1)
telnetd: /bin/login: Cannot run a file that does not have a valid format.
.
而 ssh 登录显示正常。
从错误提示, /bin/login 文件格式有问题,参照正常系统做一番简单检查,就可以看到:
# ls -l /bin/login
lrwxrwxrwx 1 root security 13 Oct 10 09:07 /bin/login -> /usr/sbin/tsm
# ls -l /usr/sbin/tsm
-r-sr-xr-x 1 root security 0 Dec 09 12:19 /usr/sbin/tsm
# file /usr/sbin/tsm
/usr/sbin/tsm: empty
# cat /usr/sbin/tsm
/usr/sbin/tsm 文件被清空了,导致了 telnet 登录失败。
从另一台主机上拷贝 /usr/sbin/tsm 之后, telnet 恢复正常。
然而,系统重启后,同样的故障再次出现:
telnetd: /bin/login: Cannot run a file that does not have a valid format.
这样看来,系统中仍存在隐患故障点,导致了 /usr/sbin/tsm 每次重启过程中都会被清空。
从实际情况看, /usr/sbin/tsm 文件仍然存在,访问权限也未变化。这说明在重启过程中的破坏性动作很可能是一次类似 ”> /usr/sbin/tsm” 的清空文件操作。
下一步需要定位 /usr/sbin/tsm 文件为何被清空。
AIX 从 4.3 版本开始就提供了 Audit 审计功能,能够对关键系统操作进行记录。详细的介绍文档可以参考:
http://www.redbooks.ibm.com/abstracts/sg246020.html
考虑到 tsm 文件被置空之前,首先需要写打开 tsm 文件,这样我们只需要监控对 tsm 文件的写打开操作即可追踪到故障点。而且考虑到 tsm 文件的权限,只有 root 用户才有权限将其置空。因此,只需要监控 root 用户下对 tsm 文件的写打开操作。
首先编辑 audit 配置文件:
#vi /etc/security/audit/config
在监控类 files 中定义了文件的各种操作:
files=FILE_Open,FILE_Read,FILE_Write,FILE_Close,FILE_Link,FILE_Unlink,FILE_Rename,FILE_Owner,FILE_Mode,FILE_Acl,FILE_Privilege,DEV_Create,File_copy
考虑到系统中文件操作很多,直接监控 files 类日志信息量太大不方便定位问题,因此考虑只将 FILE_Open 监控事件加入到默认的 general 类中。
修改如下,在 general 类中增加 FILE_Open 事件监控:
general = USER_SU,PASSWORD_Change,FILE_Unlink,FILE_Link,FILE_Rename,FS_Chdir,FS_Chroot,PORT_Locked,PORT_Change,FS_Mkdir,FS_Rmdir ,FILE_Open
audit 日志默认以二进制方式记录,可以通过 auditpr 命令转换为文本方式。本处为方便问题定位,直接将记录方式改为 stream 方式,以文本格式记录系统监控事件。修改如下:
将 streammode 设置为 on ,而 binmode 设置为 off:
# cat /etc/security/audit/config
start:
ignorenonexistentity = no
binmode = off
streammode = on
...
经过修改的 audit 配置文件:
# cat /etc/security/audit/config
start:
ignorenonexistentity = no
binmode = off
streammode = on
bin:
trail = /audit/trail
bin1 = /audit/bin1
bin2 = /audit/bin2
binsize = 10240
cmds = /etc/security/audit/bincmds
freespace = 65536
backuppath = /audit
backupsize = 0
bincompact = off
stream:
cmds = /etc/security/audit/streamcmds
streamcompact = off
classes:
general = USER_SU,PASSWORD_Change,FILE_Unlink,FILE_Link,FILE_Rename,FS_Chdir,FS_Chroot,PORT_Locked,PORT_Change,FS_Mkdir,FS_Rmdir,FILE_Open
objects = S_ENVIRON_WRITE,S_GROUP_WRITE,S_LIMITS_WRITE,S_LOGIN_WRITE,S_PASSWD_READ,S_PASSWD_WRITE,S_USER_WRITE,AUD_CONFIG_WR
SRC = SRC_Start,SRC_Stop,SRC_Addssys,SRC_Chssys,SRC_Delssys,SRC_Addserver,SRC_Chserver,SRC_Delserver
kernel = PROC_Create,PROC_Delete,PROC_Execute,PROC_RealUID,PROC_AuditID,PROC_RealGID,PROC_Environ,PROC_Limits,PROC_SetPri,PROC_Setpri,PROC_Privilege,PROC_Settimer
files = FILE_Open,FILE_Read,FILE_Write,FILE_Close,FILE_Link,FILE_Unlink,FILE_Rename,FILE_Owner,FILE_Mode,FILE_Acl,FILE_Privilege,DEV_Create,File_copy
svipc = MSG_Create,MSG_Read,MSG_Write,MSG_Delete,MSG_Owner,MSG_Mode,SEM_Create,SEM_Op,SEM_Delete,SEM_Owner,SEM_Mode,SHM_Create,SHM_Open,SHM_Close,SHM_Owner,SHM_Mode
mail = SENDMAIL_Config,SENDMAIL_ToFile
cron = AT_JobAdd,AT_JobRemove,CRON_JobAdd,CRON_JobRemove,CRON_Start,CRON_Finish
tcpip = TCPIP_config,TCPIP_host_id,TCPIP_route,TCPIP_connect,TCPIP_data_out,TCPIP_data_in,TCPIP_access,TCPIP_set_time,TCPIP_kconfig,TCPIP_kroute,TCPIP_kconnect,TCPIP_kdata_out,TCPIP_kdata_in,TCPIP_kcreate
ipsec = IPSEC_chtun,IPSEC_export,IPSEC_gentun,IPSEC_imptun,IPSEC_lstun,IPSEC_mktun,IPSEC_rmtun,IPSEC_chfilt,IPSEC_expfilt,IPSEC_genfilt,IPSEC_trcbuf,IPSEC_impfilt,IPSEC_lsfilt,IPSEC_mkfilt,IPSEC_mvfilt,IPSEC_rmfilt,IPSEC_unload,IPSEC_stat,IKE_tnl_creat,IKE_tnl_delet,IPSEC_p1_nego,IPSEC_p2_nego,IKE_activat_cmd,IKE_remove_cmd
lvm = LVM_AddLV,LVM_KDeleteLV,LVM_ExtendLV,LVM_ReduceLV,LVM_KChangeLV,LVM_AvoidLV,LVM_MissingPV,LVM_AddPV,LVM_AddMissPV,LVM_DeletePV,LVM_RemovePV,LVM_AddVGSA,LVM_DeleteVGSA,LVM_SetupVG,LVM_DefineVG,LVM_KDeleteVG,LVM_ChgQuorum,LVM_Chg1016,LVM_UnlockDisk,LVM_LockDisk,LVM_ChangeLV,LVM_ChangeVG,LVM_CreateLV,LVM_CreateVG,LVM_DeleteVG,LVM_DeleteLV,LVM_VaryoffVG,LVM_VaryonVG
ldapserver = LDAP_Bind,LDAP_Unbind,LDAP_Add,LDAP_Delete,LDAP_Modify,LDAP_Modifydn,LDAP_Search,LDAP_Compare
aacct=AACCT_On,AACCT_Off,AACCT_AddFile,AACCT_ResetFile,AACCT_RmFile,AACCT_SwtchFile,AACCT_TridOn,AACCT_TridOff,AACCT_SysIntOff,AACCT_SysIntSet,AACCT_PrIntOff,AACCT_PrIntSet,AACCT_SwtchProj,AACCT_AddProj,AACCT_RmProj,AACCT_PolLoad,AACCT_PolUnload,AACCT_NotChange,AACCT_NotifyOff
wparmgtclass = WM_CreateWPAR,WM_RemoveWPAR,WM_StartWPAR,WM_StopWPAR,WM_RebootWPAR,WM_SyncWPAR,WM_CheckptWPAR,WM_ResumeWPAR,WM_RestartWPAR,WM_ModifyWPAR,WM_SetInitConf,WM_SetMonIntv,WM_SetTierMnDsc,WM_ResetConfig,WM_ModifyConfig
users:
root = general
role:
启动 audit 命令后,就可以在 /audit/stream.out 文件上看到审计日志了:
#audit start
从以下 /audit/stream.out 输出看,记录过于简单,看不出打开的文件名:
event login status time command wpar name
--------------- -------- ----------- ------------------------ ------------------------------- -------------------------
FILE_Open root OK Wed Dec 09 14:22:44 2020 ksh Global
要看到 verbose方式的输出,必须进一步调整 streamcmds命令参数。
编辑 /etc/security/audit/streamcmds 命令文件,在 auditpr命令后增加 -v参数 :
# vi /etc/security/audit/streamcmds
/usr/sbin/auditstream | auditpr -v > /audit/stream.out &
然后重启 audit 服务:
# audit shutdown
auditing reset
# audit start
此时如果再写操作 tsm 文件,就能得到如下信息(为了对比,在此处做了一个 cp /usr/sbin/tsm /tmp/tsm 操作):
FILE_Open root OK Wed Dec 09 14:29:54 2020 ksh Global
flags: 67109633 mode: 644 fd: 3 filename /usr/sbin/tsm
。。。
FILE_Open root OK Wed Dec 09 14:32:37 2020 cp Global
flags: 67108864 mode: 0 fd: 3 filename /usr/sbin/tsm
FILE_Open root OK Wed Dec 09 14:32:37 2020 cp Global
flags: 67109633 mode: 100555 fd: 4 filename /tmp/tsm
注意这里的 flags 是 open 文件操作所带的参数, flags 是 int 型变量,其定义可以在 /usr/include/fcntl.h 文件里找到:
…
/* File access modes for open */
#define O_RDONLY 0
#define O_WRONLY 1
#define O_RDWR 2
这里只简单说明与本次问题定位相关的部分,考虑到只有写打开才能修改文件,只读打开可以忽略,因此只需要监控 flags 二进制表示最后两位中,有一位为 1 的情况。如果 flags 二进制值最后两位有一位为 1 ,则说明 open 参数至少设置了 O_WRONLY 或 O_RDWR 。
所以, flags: 67109633 二进制最后一位为 1 ,说明是 O_WRONLY 方式写打开。相应地, flags: 67108864 二进制最后一位是 0 ,说明是 O_RDONLY 只读方式打开。
至此,我们配置好了 /usr/sbin/tsm 文件的写打开监控方法。 接下来我们需要把监控操作添加到启动脚本中去,确保开机就能监控到文件操作。
在 /etc/inittab 中增加如下条目:
audit:23456789:once:/usr/sbin/audit start >/dev/console 2>&1 &
参考( /etc/inittab )文件,红色部分为新增:
init:2:initdefault:
brc::sysinit:/sbin/rc.boot 3 >/dev/console 2>&1 # Phase 3 of system boot
powerfail::powerfail:/etc/rc.powerfail 2>&1 | /usr/bin/alog -tboot > /dev/console # Power Failure Detection
tunables:23456789:wait:/usr/sbin/tunrestore -R > /dev/console 2>&1 # Set tunables
securityboot:2:bootwait:/etc/rc.security.boot > /dev/console 2>&1
rc:23456789:wait:/etc/rc 2>&1 | /usr/bin/alog -tboot > /dev/console # Multi-User checks
srcmstr:23456789:respawn:/usr/sbin/srcmstr # System Resource Controller
rctcpip:23456789:wait:/etc/rc.tcpip > /dev/console 2>&1 # Start TCP/IP daemons
audit:23456789:once:/usr/sbin/audit start >/dev/console 2>&1 &
重启系统以重现故障点。
从 /audit/stream.out 日志可以看到:
FILE_Open root OK Wed Dec 09 15:08:41 2020 ksh Global
flags: 67109633 mode: 600 fd: 3 filename /usr/sbin/tsm
结合 errpt 以及系统进程启动情况,可以看到 /usr/sbin/tsm 文件是在开机后被置空,而不是关机的过程中置空:
# ps -ef|grep inetd
root 2818160 2163520 0 15:08:39 - 0:00 /usr/sbin/inetd
# ps -kf|grep swapper
root 0 0 120 15:08:13 - 0:02 swapper
root 264 0 5 15:08:13 - 0:00 swapper
root 524 0 7 15:08:13 - 0:00 swapper
root 784 0 5 15:08:13 - 0:00 swapper
# uptime
03:22PM up 14 mins, 1 user, load average: 2.10, 1.94, 1.27
如上命令输出, tsm 文件修改的时间戳晚于 inetd 进程启动的事件。
从 stream.out 日志看, /usr/sbin/tsm 是被 ksh 命令置空,但系统启动过程中执行的 ksh 命令相当多,只凭这些信息没办法判断具体故障点。因此,必须引入能够记录更多信息的新监控方法,也就是下一节马上要提到的 probevue 。
从 6.1 版本开始, AIX 提供了 probevue 功能,可以用于系统动态跟踪和调试。 Probevue 的语法类似 C 语言,参考:
https://www.ibm.com/support/knowledgecenter/en/ssw_aix_72/generalprogramming/probevue_run.html
作者使用 probevue 编写了对文件修改进行监控的脚本,可以对指定文件名进行写打开监控,并记录触发问题时的执行栈、进程 id 、线程 id 、进程组 id 、父进程 id 、实际用户以及有效用户等信息:
# /probe_open.sh
usage: /probe_open.sh
NO WARRANTY IMPLIED. USE AT YOUR OWN RISK.
# pwd
/
# cat /probe_open.sh
#!/bin/ksh
#NO WARRANTY IMPLIED. USE AT YOUR OWN RISK. by Charles Chen.
if [ $# -ne 1 ]; then
echo "usage: $0 "
echo "NO WARRANTY IMPLIED. USE AT YOUR OWN RISK."
exit 0
fi
NAME_PATTERN=\\"$1\\"
export NAME_PATTERN
cat <<\\ENDMARKER > iomon.e
int open (const char *Path, int OFlag , int Mode);
int count;
@@BEGIN
{
printf("begin probing\\n");
count = 0;
}
@@syscall:*:open:entry
{
String filename[128];
int oflag;
filename = get_userstring(__arg1, -1);
oflag = __arg2 & 0x3;
if(strstr(filename, $NAME_PATTERN))
{
if(oflag != 0)
{
printf("\\n\\nProgram <%s>, Pid <%ld>, Tid <%ld> opened %s for write oflag = %d\\n", __pname, __pid, __tid, filename, oflag);
printf("Group ID: %ld, parent Pid : %ld.\\n", __pgid, __ppid);
printf("real user id = %d, effective user id = %d.\\n", __uid, __euid);
stktrace(PRINT_SYMBOLS | GET_USER_TRACE, -1);
count++;
}
}
}
@@interval:*:clock:60000
{
printf("%d event traced\\n", count);
}
ENDMARKER
probevue -o probe`date '+%Y-%m-%d-%H-%M-%S'`.out iomon.e
在 /etc/inittab 中增加如下条目:
probe:23456789:once:nohup /probe_open.sh /usr/sbin/tsm 2>&1 &
例如 :
init:2:initdefault:
brc::sysinit:/sbin/rc.boot 3 >/dev/console 2>&1 # Phase 3 of system boot
powerfail::powerfail:/etc/rc.powerfail 2>&1 | alog -tboot > /dev/console # Power Failure Detection
mkatmpvc:2:once:/usr/sbin/mkatmpvc >/dev/console 2>&1
atmsvcd:2:once:/usr/sbin/atmsvcd >/dev/console 2>&1
tunables:23456789:wait:/usr/sbin/tunrestore -R > /dev/console 2>&1 # Set tunables
securityboot:2:bootwait:/etc/rc.security.boot > /dev/console 2>&1
rc:23456789:wait:/etc/rc 2>&1 | alog -tboot > /dev/console # Multi-User checks
srcmstr:23456789:respawn:/usr/sbin/srcmstr # System Resource Controller
rctcpip:23456789:wait:/etc/rc.tcpip > /dev/console 2>&1 # Start TCP/IP daemons
audit:23456789:once:/usr/sbin/audit start >/dev/console 2>&1 &
probe:23456789:once:nohup /probe_open.sh /usr/sbin/tsm 2>&1 &
…
查看开机后生成的 probevue 日志,可以看到, pid 为 3670140 的 K shell 进程对 /usr/sbin/tsm 进行了写打开,其 group id 为 2556794 。
# cat probe2020-12-09-15-47-17.out
begin probing
Program , Pid <3670140>, Tid <9634037> opened /usr/sbin/tsm for write oflag = 1
Group ID: 2556794 , parent Pid : 3407950.
real user id = 0, effective user id = 0.
.__start+0x68
0x1000091c
0x100019d4
0x1002d288
0x1002bfc4
0x1002b150
0x10003d54
0x10002a68
0x10002980
.open64+0x38
.open+0xf4
sc_entry_etrc_point+0x4
.kopen+0x0
1 event traced
1 event traced
1 event traced
1 event traced
针对其进程 id 、父进程 id 、进程组 id 进行查看:
# ps -ef|grep 3670140
# ps -ef|grep 3407950
# ps -ef|grep 2556794
root 2556794 1966614 0 15:47:18 - 0:00 /opt/freeware/cimom/pegasus/bin/cimssys cimsys
只有进程组 id 下有对应的条目:
# proctree -a 2556794
1 /etc/init
1966614 /usr/sbin/srcmstr
2556794 /opt/freeware/cimom/pegasus/bin/cimssys cimsys
### 手工停止、启动 cimsys 服务并进行观察
观察 probevue 日志记录:
Program , Pid <2556886>, Tid <14746497> opened /usr/sbin/tsm for write oflag = 1
Group ID: 2490624, parent Pid : 2097586.
real user id = 0, effective user id = 0.
0x10000168
0x1000091c
0x100019d4
0x1002d288
0x1002bfc4
0x1002b150
0x10003d54
0x10002a68
0x10002980
.open64+0x38
.open+0xf4
sc_entry_etrc_point+0x4
.kopen+0x0
8 event traced
Program , Pid <4129008>, Tid <721131> opened /usr/sbin/tsm for write oflag = 1
Group ID: 2491198 , parent Pid : 4391016.
real user id = 0, effective user id = 0.
0x10000168
0x1000091c
0x100019d4
0x1002d288
0x1002bfc4
0x1002b150
0x10003d54
0x10002a68
0x10002980
.open64+0x38
.open+0xf4
sc_entry_etrc_point+0x4
.kopen+0x0
root 3997880 2491198 0 16:43:09 - 0:00 /usr/bin/sh /opt/freeware/cimom/pegasus/bin/cimssys.sh start cimsys
root 2097604 2294228 0 16:43:28 pts/1 0:00 grep 2491198
root 2491198 1966614 0 16:43:09 - 0:00 /opt/freeware/cimom/pegasus/bin/cimssys cimsys
1 /etc/init
1966614 /usr/sbin/srcmstr
2491198 /opt/freeware/cimom/pegasus/bin/cimssys cimsys
3997880 /usr/bin/sh /opt/freeware/cimom/pegasus/bin/cimssys.sh start cimsys
3080864 sleep 1
可以确认 tsm 文件被置空是启动 cimsys 服务触发,而且,从 probevue 监控日志输出看,停止 cimsys 、启动 cimsys 过程中各出现了一次对 /usr/sbin/tsm 置空的操作。
从追踪的记录可以看到 /opt/freeware/cimom/pegasus/bin/cimssys.sh start cimsys 脚本被执行了。由上面的跟踪情况可以推断,问题大概率是在脚本中执行 ”> /usr/sbin/tsm” 操作造成(因为 audit 和 probevue 跟踪得到的进程名为 ksh ,而不是具体的应用比如 cimsys 之类),因此 /opt/freeware/cimom/pegasus/bin/cimssys.sh 脚本有很大的嫌疑。
## 跟踪脚本执行
接下来需要对 /opt/freeware/cimom/pegasus/bin/cimssys.sh start cimsys 执行过程进行检查以及跟踪。
### 检查 cimssys.sh 脚本
对比本机与其他机器上的 /opt/freeware/cimom/pegasus/bin/cimssys.sh 文件,发现文件内容并未被修改。跟踪 /opt/freeware/cimom/pegasus/bin/cimssys.sh 的执行过程,发现其中主要的调用都是针对 /opt/freeware/cimom/pegasus/bin/CIMdiagd.sh 脚本,调用参数分别是 start 和 restart ,且输出都被重定向到 /dev/null 了。
手动执行 /opt/freeware/cimom/pegasus/bin/CIMdiagd.sh 脚本:
/usr/bin/kill: lrwxrwxrwx: not found.
CIM_diagd daemon already running: use first!
发现 /usr/bin/kill 报了很奇怪的错误(如上红色部分)。
对 /usr/bin/kill 命令所在的 d_stop 函数进行 set –x 跟踪:
\# /opt/freeware/cimom/pegasus/bin/CIMdiagd.sh restart
PID=3277534
PID=
PID=3277534
/usr/bin/kill: lrwxrwxrwx: not found.
CIM_diagd daemon already running: use first!
至此, /usr/bin/kill 文件有明显问题,检查 /usr/bin/kill 发现,
/usr/bin/kill: commands text
lrwxrwxrwx 1 root security 13 Oct 10 09:07 login -> /usr/sbin/tsm
**真相大白,推测在运维过程中,发生了误操作,导致将 /usr/bin****目录下的 ls –l****结果输出到了 /usr/bin/kill****文件中。结果所有的符号连接文件因为含有 ”->”****,而导致了对其源文件的清空操作。最终造成了本次开机后无法 telnet****故障,以及一系列关键系统文件被清空。**
说明:
此处为了简化命令输出,对出错的 /usr/bin/kill 进行了删减,只保留了可以说明问题的一行记录。
## 问题总结
由于 kill 命令的特殊性,通常的 shell 终端中, kill 命令为 shell 内嵌,只要不使用绝对路径执行 kill (即 /usr/bin/kill ),就不会使用到操作系统 /usr/bin/kill 命令,也不会触发 /usr/bin/kill 被误覆盖导致的问题。
从实际启动过程看,只有 cimserver 启动时中显式调用了 /usr/bin/kill ,因此触发了关键文件误覆盖故障。但整个问题其实与 cimserver 无关,只是碰巧由 cimserver 触发。而因为触发点恰好在系统启动过程中(初始化 /etc/inittab 注册项时),问题定位的复杂度略高。
定位过程中使用的 audit 方法,以及 probevue 跟踪脚本,都可以在类似问题定位中复用。稍作修改,比如修改 probevue 脚本为监控 unlink 系统调用,也可以用来跟踪文件误删除等问题( audit 方案可以直接用于监控文件误删除问题)。
## 环境恢复
从正常系统拷贝 /usr/bin/kill 命令,以及被清空的 /usr/sbin/tsm 文件(以及所有被重定向置空的文件)。
停止 audit:
杀掉 probe 脚本。从 /etc/inittab 中删除 probe 和 audit 对应的项目,然后重启机器。
## 特别说明
为维护客户隐私,所有相关数据均采用测试环境重现后抓取,请勿对号入座,谢谢!
原创文章,转载请注明出处。
如果觉得我的文章对您有用,请点赞。您的支持将鼓励我继续创作!
赞3
添加新评论0 条评论