Please be aware that the SAP SQL Anywhere Forum will be shut down on August 29th, 2024 when all it's content will be migrated to the SAP Community.

disconnecting unused connection

1

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

asked 29 Nov '22, 06:41

Ilia63's gravatar image

Ilia63
1.2k●54●59●82
accept rate: 44%

edited 29 Nov '22, 09:58

1

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.)

(29 Nov '22, 10:16) Volker Barth
Replies hidden

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'

(29 Nov '22, 11:14) Ilia63
2

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)?

(30 Nov '22, 09:45) JBSchueler
One Answer:
active answersoldest answersnewest answerspopular answers
2

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.

permanent link

answered 30 Nov '22, 09:34

JBSchueler's gravatar image

JBSchueler
3.3k●4●16●65
accept rate: 20%

edited 30 Nov '22, 09:53

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.

(30 Nov '22, 10:26) Ilia63
Replies hidden

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

(30 Nov '22, 11:05) Volker Barth

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

(02 Dec '22, 06:05) Ilia63

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

(02 Dec '22, 07:02) Volker Barth

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)

(02 Dec '22, 07:28) Ilia63

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.

(02 Dec '22, 16:15) Chris Keating
showing 2 of 6 show all flat view
Your answer
toggle preview

Follow this question

By Email:

Once you sign in you will be able to subscribe for any updates here

By RSS:

Answers

Answers and Comments

Markdown Basics

  • *italic* or _italic_
  • **bold** or __bold__
  • link:[text](http://url.com/ "title")
  • image?![alt text](/path/img.jpg "title")
  • numbered list: 1. Foo 2. Bar
  • to add a line break simply add two spaces to where you would like the new line to be.
  • basic HTML tags are also supported

learn more about Markdown

Question tags:

×248

question asked: 29 Nov '22, 06:41

question was seen: 913 times

last updated: 02 Dec '22, 16:15

Related questions

Error Code -6 when applying a transaction log file (from live backup)

sysuser last login time not being updated

Backups suddenly failing

Problem using 'callback' form of 'connect', JavaScript External Environment

Error using ''sa_dbcapi_handle" in JavaScript External Environment with WIndows

SA-17 Purchase Order Suspended

Portable version of SA and MobiLink

dbconsole and SQL Anywhere 17

Is there a local HTML help available for 17.0.4?

http web service trace log is empty in sa 17.0.10.5963