disconnecting unused connection

[former_SQLA_member326303]

Today the client (SQL Anywhere Network Server Version 17.0.10.5963) encountered the following situation when connecting to the database. For example:

I. 11/29 12:01:59. Connection from 10.2.2.70:50753 assigned connection ID 1302
I. 11/29 12:02:29. Connection ID 1302: disconnecting unused connection
I. 11/29 12:02:29. Connection ID 1302: Client disconnected

or

I. 11/29 12:03:20. Connection from 10.2.2.68:51685 assigned connection ID 1515
I. 11/29 12:03:50. Connection ID 1515: disconnecting unused connection
I. 11/29 12:03:50. Connection ID 1515: disconnecting unused connection
...total 246 identical messages...
I. 11/29 12:04:35. Connection ID 1515: disconnecting unused connection
I. 11/29 12:04:35. Connection ID 1515: Client disconnected

Why did "disconnecting unused connection" happen and what does "disconnecting unused connection" repetition mean? In less than 10 minutes, the client received more than 1.4 million "disconnecting unused connection" messages (((

ps At the same time, at 12:02:30 there was the following warning:

W. 11/29 12:02:30. Task 0000022235E5FB70(Request task 1201) is trying get forbid mutex held by task 0000022235F10970(Request task 1409) for more than 60000 ms
W. 11/29 12:02:30. Task 0000022235F10970(Request task 1409) state: worker=0000022235F20280 wakend=0 waiting=8
W. 11/29 12:02:30. Worker 0000022235F20280 state: wakend=0 waiting=0 in_atomic=0 is_dedicated=0 in_critical_section=0 allow_forbid=0

[VolkerBarth]

I have no clue. Do you use connection pooling? (And no, I'm not suggesting it has to do with that, it's just a very very very wild guess.)

[former_SQLA_member326303]

Connection pooling is used. Here is the last message about pooling before the problem:

I. 11/29 11:18:22. Connection from 10.2.2.22:50071 assigned connection ID 1127
I. 11/29 11:18:22. Connection ID 1127: "dba" connected to database "D4w" from SQL Anywhere 17.0.10 (5963) client over TCPIP
I. 11/29 11:18:22. Connection ID 1127: AppInfo is IP=...;HOST=...;OSUSER=...;OS='Windows 2016 Build 19044 ';EXE='C:\\Program Files (x86)\\Microsoft Office\\Office16\\WINWORD.EXE';PID=0x7c30;THREAD=0x80ec;VERSION=17.0.10.5963;API=ODBC;TIMEZONEADJUSTMENT=660
...
I. 11/29 11:18:23. Connection ID 1127: "dba" disconnected and cached connection in pool
I. 11/29 11:18:23. Connection ID 1127: "dba" disconnected from database "D4w"
I. 11/29 11:18:23. Connection ID 1127: Client disconnected

And here are the last parameter values received by the client:

2022-11-29 12:01:00.012,'ConnCount','835'
2022-11-29 12:01:00.012,'ConnPoolCachedCount','0'
2022-11-29 12:01:00.012,'ConnPoolHits','0'
2022-11-29 12:01:00.012,'ConnPoolMisses','0'
2022-11-29 12:01:00.012,'HttpConnPoolCachedCount','0'
2022-11-29 12:01:00.012,'HttpConnPoolHits','0'
2022-11-29 12:01:00.012,'HttpConnPoolMisses','0'
2022-11-29 12:01:00.012,'HttpConnPoolSteals','0'

[jack_schueler]

Re: In less than 10 minutes, the client received more than 1.4 million When you say "client" do you mean "customer"? The "client" is usually the application that is communicating with the "server". This almost seems like a DOS (denial of service) attack. Are all these 1.4 million coming from the same few IP addresses? Do you recognize the IP addresses (are they known addresses)?

[jack_schueler]

This disconnect happens when the server has not received a packet from the client in the past 30 seconds (the default setting) after initiating a connect. Something has prevented the client from sending or the server from receiving a packet.

The maximum number of seconds between the connection acceptance and the receipt of the first packet is 30 seconds. If the first packet is not received within this time period, the connection is dropped.

The message about the forbid mutex might indicate that a thread in the server is blocking other threads from running, including the thread that addresses incoming packets in a timely manner.

[former_SQLA_member326303]

I formulated incorrectly. More than 1.4 million messages were received by the SQL Anywhere log (-o).
The first message does arrive after 30 seconds, and then they start pouring in without interruption.
At first glance, the connections are trying to establish real users. In 10 minutes:
- about 3K such attempts were made:

I. 11/29 12:00:02. Connection from XX.X.X.XX:XXXXX assigned connection ID 1208
I. 11/29 12:00:21. Connection from XX.X.X.YY:YYYYY assigned connection ID 1209
...
I. 11/29 12:10:48. Connection from XX.X.X.ZZ:ZZZZZ assigned connection ID 4142

- about 3.4K client disconnect messages:

I. 11/29 12:00:02. Connection ID 1208: Client disconnected
I. 11/29 12:00:31. Connection ID 1211: Client disconnected
...
I. 11/29 12:11:19. Connection ID 4142: Client disconnected

- and 1422K messages that I can't interpret:

I. 11/29 12:01:58. Connection ID 1249: disconnecting unused connection
I. 11/29 12:01:58. Connection ID 1250: disconnecting unused connection
..
I. 11/29 12:11:19. Connection ID 4142: disconnecting unused connection

I can send you a server log or a summary of these disconnects.

[VolkerBarth]

Do you use Connect/ConnectFailed/Disconnect events to track those? If so, do the AppInfo, User etc. parameters or DisconnectReason show something significant?

[former_SQLA_member326303]

There are events in the database ("Connect" and "Disconnect") that write information about the connection and disconnection to a special table. The last entry before the database restart was at 12:01:22.440:

233357433,,2022-11-29 12:01:22.440,,567,,5457,,'d4w97.exe',5029,1244,5457,567,'Connect to D4W',...

The further life of this connection (already without recording information about the disconnect in a special table):

I. 11/29 12:01:22. Connection from XX.X.X.XX:52400 assigned connection ID 1244
I. 11/29 12:01:23. Connection ID 1244: "dba" connected to database "D4w" from SQL Anywhere 17.0.10 (5963) client over TCPIP
I. 11/29 12:01:23. Connection ID 1244: AppInfo is IP=XX.X.X.XX;HOST=...;OSUSER=...;OS='Windows 2012 Build 9200 ';EXE=C:\\D4w\\d4w97.exe;PID=0x1810;THREAD=0x4f8c;VERSION=17.0.10.5963;API=ODBC;TIMEZONEADJUSTMENT=660
I. 11/29 12:01:23. Connection ID 1244: Server character set conversion will occur
I. 11/29 12:01:26. Connection ID 1244: Character set changed to "none"
I. 11/29 12:05:07. Connection ID 1244: disconnecting client - 217 seconds since last contact
I. 11/29 12:05:07. Connection ID 1244: Disconnected TCPIP client's AppInfo is IP=XX.X.X.XX;HOST=...;OSUSER=...;OS='Windows 2012 Build 9200 ';EXE=C:\\D4w\\d4w97.exe;PID=0x1810;THREAD=0x4f8c;VERSION=17.0.10.5963;API=ODBC;TIMEZONEADJUSTMENT=660

[VolkerBarth]

So is this an expected user/app connecting to the database? If so, could you have them use client logging (via connection parameter LOGFILE=...)?

[former_SQLA_member326303]

ps Maybe it's time for a checkpoint and everything is frozen?

I. 11/29 11:39:54. Starting checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 11:39
I. 11/29 11:40:31. Finished checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 11:40
I. 11/29 11:48:33. Starting checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 11:48
I. 11/29 11:48:33. Finished checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 11:48
I. 11/29 11:54:48. Starting checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 11:54
I. 11/29 11:54:48. Finished checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 11:54
I. 11/29 12:20:11. Database recovery in progress
I. 11/29 12:20:11.     Last checkpoint at Tue Nov 29 2022 11:54
I. 11/29 12:20:46. Starting checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 12:20
I. 11/29 12:20:46. Finished checkpoint of "D4w" (D4w.db) at Tue Nov 29 2022 12:20

"When a checkpoint of a database occurs all of the database connections get (temporarily) locked out so that changes to the database do not occur. Normally the lock out time is very short but if you have a very large cache and there are a lot of dirty (changed) database pages then the time it takes to write all of the dirty pages to disk could take a long time..." (Mark Culp https://sqlanywhere-forum.sap.com/questions/20132/sqla0001tmp-server-unresponsive)

[chris_keating]

Do you have access to technical support? We should investigate the forbid mutex warning but it will require some setup that would be best done in a support incident.