I have five CentOS 6 linux systems at work, and encountered a rather strange issue that only seems to happen with my userid across all the linux systems I have... This is an example of the problem from entries I excepted from the last
command...
mpenning pts/19 Fri Nov 16 10:32 - 10:35 (00:03)
mpenning pts/17 Fri Nov 16 10:21 - 10:42 (00:21)
bill pts/15 sol-bill.local Fri Nov 16 10:19 - 10:36 (00:16)
mpenning pts/1 192.0.2.91 Fri Nov 16 10:17 - 10:49 (12+00:31)
kkim14 pts/14 192.0.2.225 Thu Nov 15 18:02 - 15:17 (4+21:15)
gduarte pts/10 192.0.2.135 Thu Nov 15 12:33 - 08:10 (11+19:36)
gduarte pts/9 192.0.2.135 Thu Nov 15 12:31 - 08:10 (11+19:38)
kkim14 pts/0 :0.0 Thu Nov 15 12:27 - 15:17 (5+02:49)
gduarte pts/6 192.0.2.135 Thu Nov 15 11:44 - 08:10 (11+20:25)
kkim14 pts/13 192.0.2.225 Thu Nov 15 09:56 - 15:17 (5+05:20)
kkim14 pts/12 192.0.2.225 Thu Nov 15 08:28 - 15:17 (5+06:49)
kkim14 pts/11 192.0.2.225 Thu Nov 15 08:26 - 15:17 (5+06:50)
dspencer pts/8 192.0.2.130 Wed Nov 14 18:24 still logged in
mpenning pts/18 alpha-console-1. Mon Nov 12 14:41 - 14:46 (00:04)
You can see two of my pts login entries above that do not have a source IP address associated with them. My CentOS machines have as many as six other users that share the systems. Approximately 10% of my logins see this issue, but no other usernames exhibit this behavior. There is no entry in /var/log/secure
for the entries without a source IP address.
Questions
Given the kind of scripts I keep on these systems (which control much of our network infrastructure), I'm a little spooked by this and would like to understand what would cause my logins to occasionally miss source addresses.
- Why does
last -i
show0.0.0.0
for pts line entries (also see this answer) - Is there anything (other than malicious activity) that would reasonably explain the behavior?
- Other than bash history timestamping, are there other things I can do to track the issue down?
Informational
Since this started happening, I enabled bash
history time-stamping (i.e. HISTTIMEFORMAT="%y-%m-%d %T "
in .bash_profile
) and also added a few other bash history hacks; however, that does not give clues to what happened during the previous occurrences.
All the systems run CentOS 6.3...
[mpenning@typo ~]$ uname -a
Linux typo.local 2.6.32-279.9.1.el6.x86_64 #1 SMP Tue Sep 25 21:43:11 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux
[mpenning@typo ~]$
EDIT
If I use last -i mpenning
, I see entries like this...
mpenning pts/19 0.0.0.0 Fri Nov 16 10:32 - 10:35 (00:03)
mpenning pts/17 0.0.0.0 Fri Nov 16 10:21 - 10:42 (00:21)
Note for those trying to answer: I have not logged in with the screen
command or the GUI. All my logins are from SSH; to receive the bounty award, you must cite authoritative references to explain the last -i
0.0.0.0
entries sourced only via SSH.
EDIT 2 (for ewwhite's questions)
/etc/resolv.conf
(note that I used .local
addrs in last
output above to hide my company's info)
[mpenning@sasmars network]$ cat /etc/resolv.conf
nameserver 192.0.2.40
nameserver 192.0.2.60
domain mycompany.com
search mycompany.com
[mpenning@sasmars network]$
/etc/hosts
info (note that this customized hosts file only exists on one of the machines that has these problems)
[mpenning@sasmars network]$ cat /etc/hosts
127.0.0.1 localhost.localdomain localhost
192.0.2.44 sasmars.mycompany.com sasmars
::1 localhost6.localdomain6 localhost6
## Temporary kludge until I add reverse hostname mappings...
## Firewalls
192.0.2.254 a2-inet-fw1
192.0.2.253 a2-inet-fw2
192.0.2.254 a2-wan-fw1
192.0.2.253 a2-wan-fw2
192.0.2.201 a2-fab-fw1
192.0.2.202 a2-fab-fw2
192.0.2.203 t1-eds-fw1
192.0.2.42 sasvpn
192.0.2.246 sasasa1
192.0.2.10 sasoutfw1
## Wireless
192.0.2.6 saswcs1
192.0.2.2 l2wlc3
192.0.2.4 l2wlc4
192.0.2.12 f2wlc5
192.0.2.16 f2wlc6
192.0.2.14 f2wlc1
192.0.2.8 f2wlc2
[mpenning@sasmars network]$
sftp
Output from /var/log/secure
*
Dec 26 10:36:37 sasmars sshd[26016]: pam_sm_authenticate: called (pam_tacplus v1.3.7)
Dec 26 10:36:37 sasmars sshd[26016]: pam_sm_authenticate: user [mpenning] obtained
Dec 26 10:36:37 sasmars sshd[26016]: tacacs_get_password: called
Dec 26 10:36:37 sasmars sshd[26016]: tacacs_get_password: obtained password
Dec 26 10:36:37 sasmars sshd[26016]: pam_sm_authenticate: password obtained
Dec 26 10:36:37 sasmars sshd[26016]: pam_sm_authenticate: tty [ssh] obtained
Dec 26 10:36:37 sasmars sshd[26016]: pam_sm_authenticate: rhost [192.0.2.91] obtained
Dec 26 10:36:37 sasmars sshd[26016]: pam_sm_authenticate: trying srv 0
Dec 26 10:36:38 sasmars sshd[26016]: Accepted password for mpenning from 192.0.2.91 port 55118 ssh2
Dec 26 10:36:38 sasmars sshd[26016]: pam_sm_setcred: called (pam_tacplus v1.3.7)
Dec 26 10:36:38 sasmars sshd[26016]: pam_unix(sshd:session): session opened for user mpenning by (uid=0)
Dec 26 10:36:38 sasmars sshd[26018]: pam_sm_setcred: called (pam_tacplus v1.3.7)
Dec 26 10:36:38 sasmars sshd[26018]: subsystem request for sftp
Dec 26 10:37:20 sasmars sshd[26016]: pam_unix(sshd:session): session closed for user mpenning
Dec 26 10:37:20 sasmars sshd[26016]: pam_sm_setcred: called (pam_tacplus v1.3.7)
FINAL RESOLUTION
See my answer below
This looks absolutely puzzling to me. Either it should use some DNS name or IP address. I checked the
last.c
file also but I still can't find why it is not showing anything. Probably given some time, I can figure out the part about 0.0.0.0.The two global variables used in the context are these.
So, in theory, it should either use dns or IP.
I will see if I can dig anything further. But what ewwhite asked are valid questions.
(1) Base on OP
last
outputAfter log in via ssh, one can ssh to localhost and get 0.0.0.0 in
last -i
for the later.Base on first four lines of OP's log
pts/19
log in was withinpts/17
log in period.pts/17
log in was withinpts/1
log in period.For this specific occurrence, it is logical to guess that OP ssh from 192.0.2.91(
pty/1
), then within that ssh session, log in locally (ssh localhost
) to the server again(pts/17
), and again(pts/19
).Please check if this overlapping happen with other occurrence.
Following may help pin point the cause
(2) Additional Secnario
Scenario 1 - sudo and terminal
xhost + localhost
su - UserB
orsudo su - UserB
then open a new terminal (xterm, gnome-terminal, etc)UserB
will show up as 0.0.0.0 inlast -i
su - UserB
will not register as aUserB
login in last, but opening a terminal will.Scenario 2 - login
sudo login
last
andlast -i
last
show no hostname or IP for thelogin session
.last -i
will IP 0.0.0.0 for thelogin session
.Mife's answer already show code block of
last.c
. The reasonlast
display empty hostname/IP is becauseut_host
for those records are actually empty. For complete wtmp structure, doman wtmp
on any linux system.The 2 scenarios here shows that even standard packages, under certain situation, do create them as such.
(3) Bash History Hack
It will only work if the session use
bash
as interactive shell..bashrc
and.bash_profile
are only used bybash
.They won't be sourced automatically if the session use any other shell(sh, csh, etc) or execute program directly, and there will be no bash history either.
(4) Process Accounting
Since OP mention nothing about
secure
file, I will assume that is a dead end and it actually provide now hint.If the following assumption is correct
auth.log(debian)/secure(CentOS) will not help. As only authentication related action is recorded in it.
wtmp/utmp, with the limitation in their data structure, is also a dead end. There is no information about what created them.
That leave us with one option, process accounting. This is a big gun and has to be used with caution.
The psacct package version should be 6.3.2-56 or above, according to this post.
If this is to be used, and
/var/log
has limited space, change the acct log file to a directory(root only access) under/home
, which usually has much more space.This is really the big gun. With OP 10% occurrence rate, there should be result within a week. If during that period, empty entry show up in
last
but nothing from acct log, it become a mystery situation, and would require some drastic action.Following is a sample output of
lastcomm
You can also use 'dump-acct' to show more info.
PS1: I tried to open a few terminal and ssh session. It is not clear (or not easy to pin point) what open a new pts. However, it does show everything that ran within that pts/session.
PS2: A blog post about using acct by a Mike.
So I've ran last in a debugger which hopefully will give you at least some answers to your question. My feeling is the root cause is deeper though.
Why does last -i show 0.0.0.0 for pts line entries
The best way to explain this is what happens when you dont pass -i.
The reason for this is in this code section of
last.c
Both
usedns
anduseip
(using the default options) are not flagged. This causes the logic to copy out of the structp->ut_host
which according toman utmp
contains the remote login name as recorded by whatever wrote into theutmp
.In your case, the value in here is zeroes. This is why when you run
last
nothing appears for you.In the case of
last -i
then dns_lookup is invoked. This will pass the entry (p->ut_addr_v6) to be resolved via DNS. In your case this value also contains zeroes.Most of
dns_lookup
is window dressing and heusteric. Basically what matters is the functiongetnameinfo
. This is a library call which in this case will try its best to resolve the binary value stored in theut_addr_v6
. When this entry contains zeroes (such as in your case) you are actually resolving this to0.0.0.0
as is what happens with yourlast -i
output.Is there anything (other than malicious activity) that would reasonably explain the behavior?
Well, its probably a bug or oversight. Its unlikely to be malicious since it seems stupid to leave any trace as an attacker rather than omitting a source address.
The focus of answers so far have been looking at the wrong place.
last
just readsutmp
orwtmp
. Howeverlast
is doing its best with the data it has.Your root cause lies somewhere in the manner to which
utmp
is being written to!While a few applications directly write into
utmp
I guess the source of your problems lie in the waysshd
is handling the session management.Other than bash history timestamping, are there other things I can do to track the issue down?
utmp
is not typically writable and is not meant to be.utmp
is written by applications designed to log you in and setup your session. In your case that issshd
.Why sshd is not handling your user properly is very strange as it should be properly copying in the hostname you came in from. This is where debugging efforts should probably be focused. Start with adding debug output of sshd to your logs and see if anything anomalous comes up.
If you want to work around the problem (or, maybe even possibly discover more about the issue) you can use
pam_lastlog
to manageutmp
by adding it to the session entry to /etc/pam.d/sshd.As a matter of fact it wont hurt to check if it is already there -- because
pam_lastlog
contains anohost
option which would definitely explain your behaviour you are experiencing.Finally, you could not use last at all.
aulast
does the same job via the audit subsystem.Might be worth a try to see if that has managed to at least write the correct address. If it hasn't then your problem must be with sshd as sshd is passing the DNS names around different subsystems like utmp or audit.
When you login to a Machine, these could be few entries in the last command.
The First entry with tty* comes when you login through the terminal or console by pressing CTRL+ALT+F1-6. Its pretty much clear from the terminal it's using.
The second Entry normally comes into picture when you log into a Machine and open up a terminal window in GUI. There will also be a entry even if you open a new Tab in the same terminal window.
The Third type of Entry comes when you open a screen session after loggin into through SSH. That will also create a entry there and without any IP address.
The fourth entry is pretty normal which everyone understands.
If you do
last -i
with the following entries, you will see something like this:I am pretty much sure that your case comes under in any of the 2 cases, one with the terminal Window in GUI and the other with the screen session.
Hope this Helped.
script
behavior differences between RedHat and DebianLinked Libraries
CentOS 6.3 - script (util-linux-ng 2.17.2)
Ubuntu 12.04 - script (util-linux 2.20.1)
PTY
Base on upstream source code,
script
from both versions do open new pty. Following is test.Ubuntu 12.04
Ubuntu 12.04
script
did open a new pts(2). It just did not update/var/log/wtmp
.CentOS 6
I am skipping the test as we already know that
script
do open pty and register with wtmp.libutemper
So the main difference seems to be the extra library(
libutempter.so.0
) CentOSscript
linked with.Test with Ubuntu 12.04
Compiling
script
with libutempterTesting
Before running
script
Within
script
After
script
endThe root cause of emtpy hostname
And yes,
script.c
do create thewtmp
entry with empty hostname. Look at following code block inutil-linux-2.20.1/term-utils/script.c
Line:245-247Base on
libutempter-1.1.5/utempter.h
So
script.c
is actually passing empty hostname intoutempter_add_record
.RedHat Backport
The interesting thing is, upstream
util-linux-ng-2.17.2
actually does not supportlibutempter
. Seems Redhat decided to added that support back.The above command return empty result.
Conclusion
So the difference in behavior between the two distros is not a bug, but a choice. RedHat decided to support that feature, while Debian skipped it.
I checked across 12 multi-user CentOS and RHEL 6.3-based application servers. None exhibited this behavior. There were no missing entries in
last
output going back 4-5 weeks.I think it would be important to see your
/etc/hosts
file entry to make sure it conforms to this format.Also, what are you doing for DNS resolution? Can you post your
/etc/resolv.conf
?The other responses indicating that
0.0.0.0
represents local connections are correct. The typical examples are reboot and console login events:Since this only seems to occur with named users, is there any change there's something funky being sourced or run in their login scripts? Have you changed
~/.bashrc
or~/.bash_profile
from default? Are there any other special login scripts in the environment?--Edit--
I'm still unable to reproduce this in any way. I look at two critical components, though. The
last
command is stable and has not been changed in a long time. Looking at the changelog for sysvinit-tools, there are no relevant bugs. Same for initscripts (wtmp).If you can force this to happen, try it with a different user account from the same source machines. But I don't see any indication that this is an OS issue.
I don't think we're going to get far with this without debugging last.c, but that shouldn't not too hard as it compiles readily ...
One possibility though is to dump the /var/log/wtmp file using the utmpdump command and have a look at the raw records this may shed some light for you. If not please post some relevant output from
so that we can recreate local copies of your wtmp to debug with
FINAL RESOLUTION
I already awarded the bonus, so this is purely for future googlers with the same question.
The reason this only appears in ~10% of my logins is because when I make major changes to our routers or switches, I use
script foo.log
so I have a complete terminal log of the change. For reasons I still don't understand, CentOS creates apts
entry when you use thescript
command... I will demonstrate the output oflast -i
before and after runningscript
...This behavior seems to be unique to CentOS 6... we have some CentOS 4.7 machines in the lab that don't put a blank entry in
wtmp
... Debian / Gentoo machines don't exhibit this behavior either. Our linux-admins are scratching their heads why CentOS would intentionally add anotherpts
entry when you executescript
... I suspect this is a RHEL bug.EDIT: I filed this problem as RHEL Bug id 892134
NOTE
Some people have erroneously assumed I put
script
in my~/.bashrc
or~/.bash_profile
. This is a flawed argument... if that was true, mywtmp
should have a0.0.0.0
entry after every one of my ssh logins...Of course, that was not the case...
Pseudo Terminal Slave (pts) connections are SSH or telnet connections that means indirect connections to the system. All of these connections can connect to a shell which will allow you to issue commands to the computer. So when you open up a terminal on your system from gui, it opens up a pts with source ip 0.0.0.0. From the information provided by you, it seems that it happening because of script running on this server or scheduled, which is using ssh or telnet service or local pts to throw output in terminal.
Which ssh client do you use? Some ssh clients can multiplex multiple terminals over one connection and I notice all your sessions without IP fall within longer sessions which do have a logged IP.
I can't duplicate this behaviour with ssh here.