How do I determine if proper shutdown was done?

[sfcredfox]

Greetings Experts,

I am looking for information on logs and how to determine if my last shutdown was a proper one.

Question: What specific lines would one find in the logs (which log?) that would indicate that the shutdown was a proper one? Will I be able to tell whether an entry is missing or by an entry being present that the shutdown was clean or not?

Situation: I had a 15 min. power failure today, which kicked off a UPS shutdown. My management server initiated a shutdown routine that powers down VM's, ESX hosts, the FreeNAS server, and other equipment in a rack.

I have been searching the forums and google to find log indicators of a clean vs. dirty shutdown. Through checking logs from the UPS (mind you that the UPS is not directly connected/managed by FreeNAS), it physically cut output power to the rack at 1106AM. The last log in /var/logs/messages is at 1101AM before switching over to the boot up logs. You can see the timeouts where FreeNAS looses its iSCSI connections as the ESX hosts shutdown and FreeNAS can't talk to IXsystems. There are no other helpful messages. The shutdown of FreeNAS is initiated by the management host using putty (plink) to log in as root, and delievering a 'shutdown -p now'

From what I can tell (I don't have good experience with FreeBSD logs), it doesn't look like any death messages during boot. Any thoughts/insights would be helpful.



FreeNAS 9.3-Stable 64-bit

Show : Main System

FreeNAS Platform:
SuperMicro 826 (8XDTN+)
(x2) Intel(R) Xeon(R) CPU E5200 @ 2.27GHz
72GB RAM ECC (Always!)
APC3000 UPS (Always!)

Show : Peripherals

Intel Pro 1000 (integrated) for CIFS
Two Intel Pro 1000 PT/MT Dual Port Card (Four total ports for iSCSI)
Two SLOGS (one for each iSCSI pool) - Intel 3500 SSD
IBM M1015 (IT Mode) HBA (Port 0) -> BPN-SAS2-826EL1 (12 port backplane with expander)
IBM M1015 (IT Mode) HBA (Port 0) -> SFF-8088 connected -> HP MSA70 3G 25 bay drive enclosure
HP SAS HBA (Port 0) -> SFF-8088 connected -> HP DS2700 6G 25 bay drive enclosure

Show : Pools

Pool1 (VM Datastore) -> 24x 3G 146GB 10K SAS into 12 vDev Mirrors
Pool2 (VM Datastore) -> 12x 6G 300GB 10K SAS into 6 vDev Mirrors
Pool3 (Media Storage) -> 8x 3G 2TB 7200 SATA into 1vDev[Z2]

Show : Network Scheme

Network Infrastructure:
Cisco SG200-26 (26 Port Gigabit Switch)

Four separate vLANs/subnets for iSCSI

• em2 - x.x.101.7/24
• em3 - x.x.102.7/24
• em0 - x.x.103.7/24
• em1 - x.x.104.7/24

Separate vLAN/subnet for CIFS (Always!)

• itb - x.x.0.7/24

 

[Mirfster]

Should see info in the debug. May want to check "/data/crash".

Try checking out @cyberjock 's response in: Debugging spontaneous reboots

 

[sfcredfox]

Should see info in the debug. May want to check "/data/crash".

Try checking out @cyberjock 's response in: Debugging spontaneous reboots

Thanks for the suggestion. I didn't find anything there useful to this incident. It actually had a log from a month ago around the time a drive failed. I think this is talking about that failed drive:


Panic String: I/O to pool 'Tier1-Group2' appears to be hung on vdev guid 18034775194814611868 at '/dev/gptid/8e098f7a-bad4-11e5-ae7b-0025902b18fa'

root@build3.ixsystems.com:/tank/home/jkh/build/FN/objs/os-base/amd64/tank/home/jkh/build/FN/FreeBSD/src/sys/FREENASI/O to pool 'Tier1-Group2' appears to be hung on vdev guid 18034775194814611868 at '/dev/gptid/8e098f7a-bad4-11e5-ae7b-0025902b18fa'.Version String: FreeBSD 9.3-RELEASE-p16 #1 r281084+74d0d7a: Mon Jun 29 14:32:16 PDT 2015

Nothing else useful.

 

[Mirfster]

Not sure if this is the correct place or not, but yesterday I did reboot my Server. So, looking through the debug logs I saw this in the "ixdiagnose\log\auth.log":

Feb 19 09:19:12 ASC-FREENAS01 shutdown: reboot by root:

So perhaps check that log, because it shows me entries both pertaining to "shutdown: power-down by root:" and "shutdown: reboot by root:" along with Date/Time (would be nice if they included the year as well...)

 

[sfcredfox]

Not sure if this is the correct place or not, but yesterday I did reboot my Server. So, looking through the debug logs I saw this in the "ixdiagnose\log\auth.log":
So perhaps check that log, because it shows me entries both pertaining to "shutdown: power-down by root:" and "shutdown: reboot by root:" along with Date/Time (would be nice if they included the year as well...)

That was a good suggestion, but I was not able to find any shutdown entries in there. I only found a reboot entry from a few weeks earlier, so that might indicate the shutdown was not a proper one. I wasn't able to find any freak out messages from the boot up, so maybe I'm either lucky, or an ssh shutdown gets logged somewhere else.

Thanks for the suggestions.

 

[Mirfster]

Okay, so here is what I tested:

1. SSH'd (Putty) to FreeNas
2. Entered Command to Reboot: shutdown -r now
3. Reconnected via SSH (Putty); once Reboot completed
   
4. Checked the "auth.log" for instances of 'shutdown'
   • Entered Command: more /var/log/auth.log | grep 'shutdown'
5. Output shows the entry where I issued the command via SSH (it is the last entry)

Code:

[root@ASC-FREENAS01] ~# more /var/log/auth.log | grep 'shutdown'
Feb  2 14:02:11 ASC-FREENAS01 shutdown: reboot by root:
Feb  3 16:18:27 ASC-FREENAS01 shutdown: reboot by root:
Feb 11 08:25:15 ASC-FREENAS01 shutdown: power-down by root:
Feb 13 14:37:21 ASC-FREENAS01 shutdown: power-down by root:
Feb 17 15:57:57 ASC-FREENAS01 shutdown: reboot by root:
Feb 19 09:19:12 ASC-FREENAS01 shutdown: reboot by root:
Feb 26 07:57:17 ASC-FREENAS01 shutdown: reboot by root:

So, I am thinking that the previous shutdown you are talking about was an improper one.

Additional option would be to have FreeNas send you an e-mail notifications at STARTUP and/or SHUTDOWN. Could put these into [Tasks] - [Init/Shutdown Scripts]
Reference: https://bugs.freenas.org/issues/1880