Determining How ASE Shutdown From An Errorlog
If you find your ASE server unexpectedly not running, the errorlog can provide some useful clues as to how it shutdown.
Obligatory anecdote:
Many years ago, I once worked a support case with a customer who had ended up with hard corruption in their database. Their errorlog showed that ASE had repeatedly rebooted, roughly 20 times over the course of the previous night. Their host was setup to automatically boot ASE when the OS started up. Each time there was no indication of why ASE had shutdown. I expressed the opinion that the lack of shutdown messages made me think the most likely cause was power being repeatedly shut off. A check of the OS logs confirmed that the host had also been rebooted many times with no indication of a polite shutdown. The problem was soon tracked down to new cleaning staff turning the power on and off in the computer lab. We didn’t investigate the corruption further, the assumption being that a hard drive abruptly losing power while writing was a reasonable cause (and the corrupt data was clearly gibberish that didn’t resemble formatted data).
Behavior for TSQL “shutdown” command (commonly called a ‘polite shutdown’):
00:0006:00000:00012:2013/07/22 09:33:58.10 server Shutdown started by user ‘sa’. SQL text: shutdown
00:0006:00000:00012:2013/07/22 09:34:00.10 server ASE shutdown by request.
00:0006:00000:00012:2013/07/22 09:34:00.10 kernel ueshutdown: exiting
00:0000:00000:00000:2013/07/22 09:34:00.10 kernel Main thread performing final shutdown.
00:0000:00000:00000:2013/07/22 09:34:00.19 kernel Blocking call queue shutdown.
00:0000:00000:00000:2013/07/22 09:34:00.20 kernel SySAM: Checked in license for 1 ASE_CORE
Behavior for TSQL “shutdown with nowait” command (commonly called an ‘abrupt shutdown’):
00:0002:00000:00014:2013/07/22 09:30:11.14 server Shutdown started by user ‘sa’. SQL text: shutdown with nowait
00:0002:00000:00014:2013/07/22 09:30:11.14 server Shutdown with nowait detected – ASE process level execution bindings will be cleared on startup.
00:0002:00000:00014:2013/07/22 09:30:11.16 server ASE shutdown by request.
00:0002:00000:00014:2013/07/22 09:30:11.17 kernel ueshutdown: exiting
00:0000:00000:00000:2013/07/22 09:30:11.18 kernel Main thread performing final shutdown.
00:0000:00000:00000:2013/07/22 09:30:11.28 kernel Blocking call queue shutdown.
00:0000:00000:00000:2013/07/22 09:30:11.80 kernel SySAM: Checked in license for 1 ASE_CORE
Behavior for OS “kill <pid>” command:
00:0006:00000:00000:2013/07/22 09:36:07.02 kernel ueshutdown: exiting
00:0000:00000:00000:2013/07/22 09:36:07.02 kernel Main thread performing final shutdown.
00:0000:00000:00000:2013/07/22 09:36:07.23 kernel Blocking call queue shutdown.
00:0000:00000:00000:2013/07/22 09:36:07.23 kernel SySAM: Checked in license for 1 ASE_CORE
Behavior for spid-fatal error while holding a spinlock:
00:0014:00000:02998:2014/01/20 03:10:23.62 kernel Spinlocks held by kpid <kpid#>
[…fatal error, typically with a stack trace…]
00:0014:00000:02998:2014/01/20 03:10:23.62 kernel Spinlock Resource-><spinlock name> at address <address> owned by <kpid#>
00:0014:00000:02998:2014/01/20 03:10:23.62 kernel End of spinlock display.
[… typically another stack trace …]
00:0014:00000:02998:2014/01/20 03:10:23.62 kernel end of stack trace, spid <spid>, kpid <kpid>, suid <suid>
00:0014:00000:02998:2014/01/20 03:10:23.62 kernel ueshutdown: exiting
[On a server running in threaded mode rather than process mode, the following additional line is also output:]
00:0000:00000:00000:2014/01/20 03:10:23.62 kernel Main thread performing final shutdown.
Behavior for an OS Panic:
00:0006:00000:00000:2013/07/22 09:36:07.02 kernel Engine 0 (os pid <pid> has died, server is performing emergency shutdown
[…]
stacktrace containing the function keipanic+0x8c (offset may vary by platform)
[…]
00:0006:00000:00000:2013/07/22 09:36:07.02 kernel ueshutdown: exiting
00:0006:00000:00000:2013/07/22 09:36:07.02kernel end of stack trace, kernel
service process: kpid 1114129
Behavior for OS “kill -9 <pid>” command:
[no output added to log].
Behavior for UNIX OS shutdown and reboot:
[no output added to log]
Behavior for abrupt power shutoff:
[no output added to log]
Other possible causes (not exhaustive) of no shutdown-related information in the errorlog:
a) Errorlog’s file system filled before the shutdown
b) Errorlog file disconnected from file descriptor used by ASE.
For example, errorlog copied to another file, original file deleted, copy renamed.
A possible hint for this is an unusual lack of entries preceeding the shutdown.
c) Errorlog could have been edited to remove information.
Hi Bret,
thanks for sharing this. I think this helps all DBA's to interpret the error logs.
I had a simular issue. The customer noticed a regurlar shutdown at about 03:30AM every 2 weeks. The system logs displayed this:
00:0000:00000:00000:2014/05/18 03:29:15.59 kernel kisignal: SQL Server terminated by system shutdown.
00:0000:00000:00000:2014/05/18 03:29:15.60 kernel ueshutdown: exiting
00:0011:00000:00000:2014/05/18 03:29:15.60 kernel Sybperf helper thread is quitting
00:0000:00000:00000:2014/05/18 03:29:15.60 kernel Main thread performing final shutdown.
00:0000:00000:00000:2014/05/18 03:29:15.65 kernel Blocking call queue shutdown.
This logs entries are displayed if it is a normal system shutdown (OS Windows) which includes a stop of the sybase services. The reason was that the customer activated the automatic windows updates. The WSUS (Windows Server Update Services) will restart the server after 3 days (policy default).
This should never be activated. You should test the updates in your test environment and implement the patches after successful test phase in QAS/PRD systems.
Regards,
Jens
To add to Jens's reply, on Windows ASE there is another shutdown sequence that can be seen when ASE is shutdown through the Services utility and is identified by the 'shutdownproc' prefix :
00:0002:00000:00003:2014/06/02 14:41:28.63 kernel shutdownproc: shutting down SQL Server!
00:0002:00000:00003:2014/06/02 14:41:28.71 server ASE shutdown by request.
00:0002:00000:00003:2014/06/02 14:41:28.71 kernel ueshutdown: exiting
Rgds
Bart van Kuijk
Hello. I am new to Sybase and taking first steps as a DBA. Here's a behaviour of my instance when a host OS is being rebooted. The host is an AIX box with version 7100-05-03-1846
00:0010:00000:00013:2019/09/10 09:53:50.28 kernel Begin processing to generate RSA keypair.
00:0010:00000:00013:2019/09/10 09:53:50.31 kernel Completed processing to generate RSA keypair.
00:0010:00000:00013:2019/09/10 09:53:50.31 kernel Begin processing to generate RSA keypair.
00:0010:00000:00013:2019/09/10 09:53:50.35 kernel Completed processing to generate RSA keypair.
00:0010:00000:00186:2019/09/10 10:51:42.71 server DBCC TRACEON 3604, SPID 186
00:0005:00000:00553:2019/09/10 21:09:57.72 server Increase the config parameter 'number of open objects' to avoid descriptor reuse. Reuse may result in performance degradation.
00:0005:00000:00004:2019/09/10 23:53:31.88 kernel shutdownproc: shutting down server
00:0005:00000:00004:2019/09/10 23:53:31.88 kernel ueshutdown: exiting
00:0005:00000:00000:2019/09/10 23:53:31.88 kernel bucket manager consolidator terminating
00:0000:00000:00000:2019/09/10 23:53:31.88 kernel Main thread performing final shutdown.
00:0000:00000:00000:2019/09/10 23:53:31.90 kernel Blocking call queue shutdown.
00:0000:00000:00000:2019/09/10 23:53:36.91 kernel SySAM: Checked in license for 6 ASE_CORE (****************************).
and that is it. no other info. I confirmed that this shutdown was due to OS reboot.
Hi Marek,
you can know it by the keyword 'ueshutdown: exiting' since if ASE was shutdown by DBA smoothly (shutdown with wait), you should get the line "ASE shutdown by request" before "kernel ueshutdown: exiting".
/* grep from ASE errorlog */
Line 2179: 00:0006:00000:00004:2019/04/07 19:31:43.80 server ASE shutdown by request.
Line 2181: 00:0006:00000:00004:2019/04/07 19:31:43.81 kernel ueshutdown: exiting
Hope this will help.
Thanks.
Best Regards,
Robert
In the time since I wrote this blog the "shutdownproc" entry mentioned by Bart has been extended by engineering to exist on UNIX platforms as well. My understanding is that this "shutdownproc" line will now be seen on UNIX platforms when a polite shutdown of the OS is performed. The OS sends a signal to the dataserver process(es), which respond via a signal handler to call the internal "shutdownproc" procedure to attempt to do a clean shutdown before the OS shuts down.
To expand on Bret's comment above, a kill -15 (or -s TERM) shows "shutdownproc" in the shutdown sequencnce:
kill -s TERM <pid> or kill -15 <pid> to send a SIGTERM to ASE:
$ kill -15 22169
End of the log
00:0002:00000:00004:2020/12/03 11:56:28.39 kernel shutdownproc: shutting down server
00:0002:00000:00004:2020/12/03 11:56:28.39 kernel ueshutdown: exiting
00:0002:00000:00000:2020/12/03 11:56:28.39 kernel bucket manager consolidator terminating
00:0000:00000:00000:2020/12/03 11:56:28.39 kernel Main thread performing final shutdown.
00:0000:00000:00000:2020/12/03 11:56:28.39 kernel Blocking call queue shutdown.