RHEL Last Command – Can’t Explain ‘Crash’ Entries in Output

lastrhel

Last shows "crash" at 12:02 and 14:18, but the system didn't stop working at that time. The reboot at 15:03, on the other hand, was to recover from an actual crash – our system stopped responding at 14:46. Why does last show two "crashes" prior to the actual crash of the machine?

[admin@devbox log]$ last | head
myuser pts/2        myhostname  Wed Sep 28 15:12   still logged in
myuser pts/2        myhostname  Wed Sep 28 15:09 - 15:12  (00:02)
myuser pts/2        myhostname  Wed Sep 28 15:07 - 15:09  (00:01)
myuser pts/1        myhostname  Wed Sep 28 15:06   still logged in
myuser pts/0        myhostname  Wed Sep 28 15:04   still logged in
reboot   system boot  2.6.18-274.el5PA Wed Sep 28 15:03          (00:09)
myuser pts/1        myhostname  Wed Sep 28 14:18 - crash  (00:44)
myuser pts/0        myhostname  Wed Sep 28 12:02 - crash  (03:01)

EDIT: The reboot at 15:03 is real enough – but the two "crash" entries at 14:18 and 12:02 I can't explain.

Best Answer

last prints crash as logout time when there is no logout entry in the wtmp database for an user session.

The last entry in last output means that myuser logged on pts/0 at 12:02 and, when system crashed between 14:18 and 15:03, it should be still logged in.

Usually, in wtmp there are two entries for each user session. One for the login time and one for the logout time. When a system crashes, the second entry could be missing. So last supposes that the user was still logged on when the system crashed and prints crash as logout time.

To be more clear, that two "crash" line are only the two session that were active when the system crashed around 15:00, not two system crash.

Related Solutions

Logs – Understanding the Output of the ‘Last’ Command

reboot and shutdown are pseudo-users for system reboot and shutdown, respectively. That's the mechanism for logging that information, with kernel versions to same place, without creating any special formats for the wtmp binary file.

Quote from man wtmp:

The wtmp file records all logins and logouts. Its format is exactly like utmp except that a null username indicates a logout on the associated terminal. Furthermore, the terminal name ~ with username shutdown or reboot indicates a system shutdown or reboot and the pair of terminal names | / } logs the old/new system time when date(1) changes it.

wtmp binary file do not save other than timestamp for events. For example, last calculates additional things, such as login times.

reboot   system boot  2.6.32-28-generi Mon Feb 21 17:02 - 18:09  (01:07)    
...
user     pts/0        :0.0             Sat Feb 12 18:52 - 18:52  (00:00)    
user     tty7         :0               Sat Feb 12 18:52 - 20:53  (02:01)    
reboot   system boot  2.6.32-28-generi Sat Feb 12 08:31 - 18:09 (9+09:37)

The last column (in parentheses) is the length of event. For the user reboot, it's uptime.

After the latest reboot, time is current uptime. For earlier reboots, time is uptime after that reboot (so in the last line of my example it's uptime until the first line; there were no reboots in between). Number(s) before + means number of days. In the last line, it's 9 days, 9 hours and 37 minutes, and in the first line current uptime is 1 hour and 7 minutes.

Note, however, that this time is not always accurate — for example, after a system crash and unusual restart sequence. last calculates it as the time between it and next reboot/shutdown.

The purpose of the 10th column of the `last` command’s output

When listing reboots, the tenth column shows the last “down time” following the boot, i.e. the time at which the system was shut down, as far as last can determine. This actually involves combining multiple records from the information stored in the system; to do so, last keeps track of the last down time it’s seen, and uses that blindly when it displays a “reboot” line.

Thus if the system is shut down abruptly, the shut down time won’t be stored, and last will use the previous record instead. Looking at your results:

reboot   system boot  3.10.0-514.21.1. Wed Dec 13 10:25 - 11:53  (01:28)    
reboot   system boot  3.10.0-514.21.1. Mon Oct 30 16:23 - 11:53 (43+20:30)  
reboot   system boot  3.10.0-514.21.1. Fri Oct 20 16:53 - 11:53 (53+20:00)  
reboot   system boot  3.10.0-514.21.1. Mon Oct 16 09:21 - 11:53 (58+03:32)  
reboot   system boot  3.10.0-514.21.1. Fri Aug 25 15:53 - 11:53 (109+21:00) 
reboot   system boot  3.10.0-514.21.1. Tue Aug 22 15:36 - 11:53 (112+21:16) 
reboot   system boot  3.10.0-514.21.1. Fri Jul 21 16:38 - 11:53 (144+20:15) 
reboot   system boot  3.10.0-514.21.1. Fri Jun  9 15:00 - 16:18 (42+01:17)  
reboot   system boot  3.10.0-514.21.1. Mon Jun  5 11:20 - 16:18 (46+04:57)  
reboot   system boot  3.10.0-514.21.1. Thu Jun  1 09:49 - 16:18 (50+06:28)  
reboot   system boot  3.10.0-514.el7.x Wed May 31 17:46 - 09:49  (16:02)

last found a record indicating a shut down at 11:53 on December 13, and then several records indicating a start time; so it used that single shut down time for all of them. Then it found a shut down record for 42 days after June 9, at 16:18, and used that, again several times because it didn’t find any other shut down record until 09:49 on June 1.

You can see this in the last source code; search for “lastdown” to find where it’s updated (and used).

Best Answer

Related Solutions

Logs – Understanding the Output of the ‘Last’ Command

The purpose of the 10th column of the `last` command’s output

Related Question