service error 1053

[Former Member]

Hi! Our sybase 12 database Engine running as a service doesn't close down as we expect. When we order a shutdown of the service, we can see that all connections immediatly are closed, but "Services" gives us error 1053. If we watch dbsrv12.exe in the taskmanager we can se that it loads the cpu with approx 25%, and keeps approx 2600 MB in ram. After about 5 minutes we can see the that the ram consumption starts to fall and the then the Engine really close. Any tips on how to debug/fix this is appreciated. Regards Janne

[MCMartin]

Please provide the exact version of your dbsrv12

[Former Member]

SQL Anywhere Network Server Version 12.0.1.3994

Workgroup Edition

Copyright © 2001-2013, iAnywhere Solutions, Inc. Portions copyright © 1988-2013, Sybase, Inc. All rights reserved. Use of this software is governed by the Sybase License Agreement. Refer to http://www.sybase.com/softwarelicenses.

[VolkerBarth]

When you shutdown the server, do the active connections have uncommitted transactions? Stopping the server will force to rollback all uncommitted transactions, and that may require some work on the server.

Does the same happen if there are no (or just a few) active connections when you stop the service?

---

FWIW: net helpmsg 1053:

"Error 1053: The service did not respond to the start or control request in a timely fashion"

[VolkerBarth]

What does the console log (dbsrv12 -o MyConsole.log) reveal? You may add the -z option to log debugging information to your server's command line. In case that is too expensive, you can also turn on debugging just before you try to shutdown the server, via

call sa_server_option('DebuggingInformation', 'YES');

(Don't forget to unset that option afterwards...)

[Former Member]

Ok, will try this next week since this is a system used 24/7 so I'm not allowed to do ANYTHING on a friday! (good rule by the way). Will this generate a log file or write to the eventlog or what?

[VolkerBarth]

These messages will not appear in the OS eventlog but in the console log file - if you have specified one with dbsrv12 -o.

If not, and you cannot re-start the server, you can also add that at runtime via

call sa_server_option('ConsoleLogFile', 'C:\\\\MyConsole.log');

[Former Member]

OK, here is the output on my logfile:

I. 01/27 10:04:54. Database server shutdown requested via server console
I. 01/27 10:04:54. Disallowing new connections
W. 01/27 10:04:54. TCPIP listener on IP address (::😞2638 is exiting
W. 01/27 10:04:54. TCPIP listener on IP address 0.0.0.0:2638 is exiting
E. 01/27 10:04:54. TCP/IP link, function WSARecvFrom, error code 995
E. 01/27 10:04:54. TCP/IP link, function WSARecvFrom, error code 995
E. 01/27 10:04:54. TCP/IP link, function WSARecvFrom, error code 995
I. 01/27 10:04:54. Shutting down databases
I. 01/27 10:04:54. Connection ID 117359: Client disconnected
I. 01/27 10:04:54. Connection ID 4: Client disconnected
I. 01/27 10:04:54. Connection ID 117359: "ABC" disconnected from database "depot_2321"
I. 01/27 10:04:54. Connection ID 4: "PLC" disconnected from database "depot_2321"
I. 01/27 10:04:54. Connection ID 14526: Client disconnected
I. 01/27 10:04:54. Connection ID 14526: "ABC" disconnected from database "depot_2321"
I. 01/27 10:04:54. Connection ID 149412: Client disconnected
I. 01/27 10:04:54. Connection ID 149412: "ABC" disconnected from database "depot_2321"
I. 01/27 10:04:54. Connection ID 1447: "EXTENV_MAIN" disconnected from database "depot_2321"
I. 01/27 10:04:54. Connection ID 161032: "ABCD" disconnected from database "depot_2321"
I. 01/27 10:04:54. Starting checkpoint of "depot_XXXX" (depot_XXXX.db) at Mon Jan 27 2014 10:04
I. 01/27 10:04:59. Finished checkpoint of "depot_XXXX" (depot_XXXX.db) at Mon Jan 27 2014 10:04
I. 01/27 10:15:23. Completing server shutdown
I. 01/27 10:15:31. Database server stopped at Mon Jan 27 2014 10:15

[VolkerBarth]

Is that a console log containing debugging information (i.e. produced with -z or sa_server_option('DebuggingInformation', 'YES'))?

Note, the lines starting with "E. " contain error messages, so there seems to be something unusual with the TCP/IP (I can't tell whether that has any influence on the slow shutdown)...

[Former Member]

Yes it is, The error has something to do with IPV6 as far as I understand, Found this in Another thread: If SA 9.0 works, then perhaps it's an IPv6 issue. Try adding this to your server start command:

-x tcpip(IPv6=NO)

This is an undocumented TCP option so don't tell anyone about it. 🙂

Trying that now. Datbase is always fast to shutdown if we do it 0-15 minutes after it's started so I'll have to wait....

[VolkerBarth]

In case you can leave a DBA connection open after the general shutdown request has been sent (and other connections have been closes) - say, after 10:05 in your above log:

Could you then query (say, with sa_conn_info) if there are still (internal) connections active?

(If your DBA connection is immediately closed with the others, well, then it's more difficult, apparently: You may then add a "DISCONNECT event" to log on-going actions, say by writing the contents of sa_conn_info or other system state information like db_property('RollbackLogPages') to the console log (via MESSAGE statements) in a loop until that event connection is closed, too...)

[jeff_albion]

FYI: When the TCP listener shuts down, seeing a '995' in the detailed console log is typical - see 'WSA_OPERATION_ABORTED' in the details of WSARecvFrom.

WSA_OPERATION_ABORTED The overlapped operation has been cancelled due to the closure of the socket.

This just means that the outstanding operations on the socket didn't complete before the socket closed. Which is understandable if the socket is being forcefully closed.

[Former Member]

-x tcpip(IPv6=NO) did not help....

Last 4 lines of the following text:

I. 01/28 08:58:44. Starting checkpoint of "depot_2321" (depot_2321.db) at Tue Jan 28 2014 08:58

I. 01/28 08:58:47. Finished checkpoint of "depot_2321" (depot_2321.db) at Tue Jan 28 2014 08:58

I. 01/28 09:06:07. Completing server shutdown

I. 01/28 09:06:11. Database server stopped at Tue Jan 28 2014 09:06

What does it do between 08:58:47 and 09:06:07,

8 minutes???????

---

I. 01/28 08:58:44. Connection ID 11169: Client disconnected

I. 01/28 08:58:44. Connection ID 3: Client disconnected

I. 01/28 08:58:44. Connection ID 3: "PLC" disconnected from atabase "depot_2321"

I. 01/28 08:58:44. Connection ID 11169: "PLC" disconnected from database "depot_2321"

W. 01/28 08:58:44. TCPIP listener on IP address 0.0.0.0:2638 is exiting

I. 01/28 08:58:44. Connection ID 71: "okq8" disconnected from database "depot_2321"

I. 01/28 08:58:44. P,71,[S]DUMMY<seq>

I. 01/28 08:58:44. Connection ID 4: "okq8" disconnected from database "depot_2321"

I. 01/28 08:58:44. P,4,[S]DUMMY<seq>

I. 01/28 08:58:44. P,4,[S]DUMMY<seq>

I. 01/28 08:58:44. E,2040,-299,Statement interrupted by user

I. 01/28 08:58:44. >,2040,EXEC

I. 01/28 08:58:44. Connection ID 2040: "EXTENV_MAIN" disconnected from database "depot_2321"

I. 01/28 08:58:44. Starting checkpoint of "depot_2321" (depot_2321.db) at Tue Jan 28 2014 08:58

I. 01/28 08:58:47. Finished checkpoint of "depot_2321" (depot_2321.db) at Tue Jan 28 2014 08:58

I. 01/28 09:06:07. Completing server shutdown

I. 01/28 09:06:11. Database server stopped at Tue Jan 28 2014 09:06