utmp文件锁住,who am i命令无法获得正常输出的解决方法

wylon

utmp文件锁住,who am i命令无法获得正常输出的解决方法

故障环境：
OS:RedFlag Linux DC Server 5.0 (2.6.9-42.15AX x86-64)
客户端A，服务器端B
故障问题：
由客户端A telnet/sshd登录服务器端B时，系统本身没有记录客户端A的信息（由后来分析结果判断只是部分信息没有更新，关键为utmp），即who am i及who –m没有任何输出
故障分析：
一.telnet/ssh登录过程，系统日志信息发生变化的系列过程
当客户端A使用telnet/ssh作登录服务器端B操作，每次有一个用户登录时:

[1]login程序在文件lastlog中察看用户的UID。如果找到了，则把用户上次登录、退出时间和主机名写到标准输出中，然后login程序在lastlog中纪录新的登录时间。

[2]在新的lastlog纪录写入后，utmp文件打开并插入用户的utmp纪录。该纪录一直用到用户登录退出时删除。utmp文件被各种命令文件使用，包括who、w、users和finger。

[3]，login程序打开文件wtmp附加用户的utmp纪录。当用户登录退出时，具有更新时间戳的同一utmp纪录附加到文件中。wtmp文件被程序last和ac使用。

utmp、wtmp和lastlog日志文件是多数重用UNIX日志子系统的关键--保持用户登录进入和退出的纪录。有关当前登录用户的信息记录在文件utmp中；登录进入和退出纪录在文件wtmp中；最后一次登录文件可以用lastlog或者utmpdump命令察看。
二.由以上分析，检查utmp、wtmp、lastlog及messages，当客户端A登录时，唯有utmp文件没有更新，且who -m/who am i命令默认是从utmp文件读取信息的

1、utmp文件无法更新

[url=]testmachine@/proc>last[/url] –f /var/run/utmp               ＃utmp并无记录新登录用户信息
simpleuser    ttyp18753                     Sun Feb 17 12:32   still logged in   
simpleuser    ttyp18226                     Sun Feb 17 12:32   still logged in   
simpleuser    ttyp23233                     Sun Feb 17 12:31   still logged in   
simpleuser    ttyp190      192.168.0.22   Sun Feb 17 12:31   still logged in   
simpleuser    ttyp180      192.168.0.22   Sun Feb 17 12:31   still logged in   
[url=]testmachine@/proc>who[/url] am i                             ＃who am I 无法取得IP地址及tty信息输出
[url=]testmachine@/proc>last[/url] | head -n 1
simpleuser    ttyp18554                     Sun Feb 17 12:33   still logged in   
[url=]testmachine@/proc>ll[/url] /var/run/utmp
-rw-rw-r--  1 root utmp 1621248 Feb 17 11:46 /var/run/utmp  ＃utmp内容一直没有更新，而wtmp、lastlog [url=]testmachine@/proc>ll[/url] /var/log/wtmp      ＃及messages都有更新，从时间点、文件大小、
-rw-rw-r--  1 root utmp 15526272 Feb 17 12:36 /var/log/wtmp   ＃文件内容都可以发现
[url=]testmachine@/proc>ll[/url] /var/log/lastlog
-rw-r--r--  1 root root 151840 Feb 17 12:36 /var/log/lastlog

2、模拟终端登录过程，检查utmp文件使用情况，发现utmp文件状态为锁住，即其他应用程序（包括客户端登录程序）需要使用utmp文件时，必须进入等待队列而导致应用程序异常
注：
在服务器端B上执行strace –f –p 1293 –o /tmp/sshd.log (-f为记录由sshd操作过程衍生进程，1293为sshd的pid)
通过在客户端A登录到服务器端B上，完成login的过程之后，中断strace看sshd.log内容

[1]显示utmp文件被锁住
注：查找utmp文件，在sshd.log里会记录
22617 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
22617 access("/var/run/utmpx", F_OK)    = -1 ENOENT (No such file or directory) ＃utmpx为utmp的一个补充，
22617 open("/var/run/utmp", O_RDWR)     = 7       ＃只要有utmp就足够了，solaris
22617 fcntl(7, F_GETFD)                 = 0       ＃上是有/var/adm/utmpx
22617 fcntl(7, F_SETFD, FD_CLOEXEC)     = 0
22617 lseek(7, 0, SEEK_SET)             = 0
22617 alarm(0)                          = 0
22617 rt_sigaction(SIGALRM, {0x2a967ddbf0, [], SA_RESTORER, 0x2a967162b0}, {0x552aab44a0, [], SA_RESTORER|SA_INTERRUPT, 0x2a967162b0}, = 0
22617 alarm(1)                          = 0
22617 fcntl(7, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0
22617 read(7, "\7\0\0\0b\6\0\0pts/2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384
22617 read(7, "", 384)                  = 0
22617 fcntl(7, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
22617 alarm(0)                          = 1
22617 rt_sigaction(SIGALRM, {0x552aab44a0, [], SA_RESTORER|SA_INTERRUPT, 0x2a967162b0}, NULL, = 0
22617 alarm(0)                          = 0
22617 rt_sigaction(SIGALRM, {0x2a967ddbf0, [], SA_RESTORER, 0x2a967162b0}, {0x552aab44a0, [], SA_RESTORER|SA_INTERRUPT, 0x2a967162b0}, = 0
22617 alarm(1)                          = 0
22617 fcntl(7, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = ? ERESTARTSYS (To be restarted)
注：下面是一个文件可以被正常读写的过程演示：
22617 open("/var/log/wtmp", O_WRONLY)   = 7
22617 alarm(0)                          = 0
22617 rt_sigaction(SIGALRM, {0x2a967ddbf0, [], SA_RESTORER, 0x2a967162b0}, {0x552aab44a0, [], SA_RESTORER|SA_INTERRUPT, 0x2a967162b0}, = 0
22617 alarm(1)                          = 0
22617 fcntl(7, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
22617 lseek(7, 0, SEEK_END)             = 16429440
22617 write(7, "\7\0\0\0YX\0\0pts/11\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384
22617 fcntl(7, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
22617 alarm(0)                          = 1
22617 rt_sigaction(SIGALRM, {0x552aab44a0, [], SA_RESTORER|SA_INTERRUPT, 0x2a967162b0}, NULL, = 0
22617 close(7)                          = 0
22617 stat("/var/log/lastlog", {st_mode=S_IFREG|0644, st_size=151840, ...}) = 0
22617 open("/var/log/lastlog", O_RDWR|O_CREAT, 0600) = 7
22617 lseek(7, 151548, SEEK_SET)        = 151548
22617 write(7, "\200\370\267Gpts/11\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 292) = 292
22617 close(7)                          = 0
22617 close(0)      



[2] krb-telnetd锁住utmp文件，查找utmp文件是因写(R)还是读(W)锁住
krb-telnetd    900     root    3uR     REG              104,2  1923072    3008272 /var/run/utmp
krb-telnetd   3004     root    3uR     REG              104,2  1294848    2992803 /var/run/utmp (deleted)
krb-telnetd   6526     root    3uR     REG              104,2  1923072    3008272 /var/run/utmp


得出utmp由哪些进程作读/写占用，将其进程杀掉后，utmp资源释放，utmp文件可以正常写，who am i及who –m命令可以正常输出
到这里为止,utmp文件无法更新问题解决。


附注：


三.再细化各日志的功能介绍：

lastlog 纪录最近几次成功登录的事件和最后一次不成功的登录
messages 从syslog中记录信息（有的链接到syslog文件）
utmp 纪录当前登录的每个用户
wtmp 一个用户每次登录进入和退出时间的永久纪录

四.日志循环：

wtmp日志循环

数据交换、关机和重起也记录在wtmp文件中。所有的纪录都包含时间戳。这些文件（lastlog通常不大）在具有大量用户的系统中增长十分迅速。例如wtmp文件可以无限增长，除非定期截取。许多系统以一天或者一周为单位把wtmp配置成循环使用。它通常由cron运行的脚本来修改。这些脚本重新命名并循环使用wtmp文件。通常，wtmp在第一天结束后命名为wtmp.1；第二天后wtmp.1变为wtmp.2等等，直到wtmp.7。

虽然utmp日志文件、wtmp是data file，但仍可以通过; > data file清空此文件（系统在启动时/etc/rc.sysinit时已作初始化及清空操作）

参考文章：
理解Linux系统的日志 http://www.ccert.edu.cn/faq/show.php?handle=69
man who
man utmp
cat /etc/rc.sysinit



[ 本帖最后由 wylon 于 2008-2-18 11:42 编辑 ]