CwclServer::Close() sometimes hangs

[david_dcl]

Hi,
I've come across an intermittent issue while using the Microsoft stack and the WCL bluetooth library. The issue is that the Close() method on the CwclServer class hangs. I have not been able to work out the specific situation when this happens, but have included a stack trace of where it hangs, which is always identical.

The general conditions
The app establishes a connection outwards using CwclClient, sends and receives some data, calls Disconnect(), then sets up the CwclServer class to listen for incoming connections. The previously connected device connects back to the app, lots of data is sent and received, then the app calls Close() to end the connection, at which point Close() never returns.

The OnClosed and OnDisconnected hooks have not fired, and the Server state is ssConnected.

Am I using the library correctly? Are there situations in which Close should not be called? Any help would be much appreciated.

version is 6.12.10.0 (also on 6.12.9.0)

Thanks very much
David

stack trace (main thread)

CwclCustomConnection::StopThread() line 138
CwclCustomServerConnection::CloseWinSock() line 221
CwclCustomServerConnection::CloseMicrosoft() line 177
CwclCustomServerConnection::CloseBluetooth() line 154
CwclCustomServerConnection::Close() line 117

in another thread:
user32.dll!_NtUserMessageCall@28()
user32.dll!_SendMessageWorker@24()
user32.dll!_SendMessageW@16()
CwclCustomServerConnection::WinSockThread() line 1328
CwclCustomServerConnection::_WinSockThread line 1348

when it is hung, it never gets past WinSockThread() line 1328

[Mike Petrichenko]

Hi,

In your software all looks correct. So it looks as a bug. Unfortunately it is hard to reproduce such issues here. It would be really great if you can do some trace on your side and provide me with a trace log. Could you please find this routine in WCL source code (wclServers.cpp)

void CwclCustomServerConnection::WinSockThread().

Then find this line there

SendMessage(GetWnd(), WCL_WM_REINIT_MS_BT_SERVER_SOCKET, 0, 0);

Please, add

OutputDebugString(L"SendMessage before");

before and

OutputDebugString(L"SendMessage after");

after that SendMessage.


In wclConnections.cpp find

void CwclCustomConnection::StopThread()

and add

OutputDebugString(L"WaitForSingleObject before");

before

WaitForSingleObject(m_hThread, INFINITE);

and

OutputDebugString(L"WaitForSingleObject after");

after that line.

Then send me a log please (You can use debugView to trace Debug output outside IDE).

[david_dcl]

The application puts out quite a bit of other debugging info which has been removed. From what you asked me to add, only two entries showed up before the application hung, waiting to return from Close()

00000416        13.15164661     [16096] SendMessage before
...
00000431        13.47376823     [16096] WaitForSingleObject before
...

Cheers
David

[Mike Petrichenko]

Thanks a lot. Will send you a fixed version as soon as possible. The bug is in WaitForSingleObject when WCL trys to terminate thread. But thread calls SendMessage to the main thread. And, of course, deadlock appears.

[Mike Petrichenko]

in wclServers.cpp find

Code: [Select]

void CwclCustomServerConnection::WinSockThread()
routine. Find

Code: [Select]

if (GetTransport() == trBluetooth)
    SendMessage(GetWnd(), WCL_WM_REINIT_MS_BT_SERVER_SOCKET, 0, 0);
lines there and change

Code: [Select]

if (GetTransport() == trBluetooth)
to

Code: [Select]

if (GetTransport() == trBluetooth && m_State == ssConnected)
This should fix the issue. Please, let me know if it does or does not.

[david_dcl]

Thanks very much for your fast replies.

The change you suggested did not solve the problem. However I did some more playing around and discovered more about the issue.

The events leading up to the issue are ...
1. The computer sends a packet to the external device (contents of which tells the device to disconnect)
2. Both ends can then pull down their bluetooth connection

the Close() function returns normally if called within a window of time after this 'disconnect' packet has been sent. If you call Close() outside this window, it will hang.

eg.

Code: [Select]

server.Write(...) // disconnect packet
server.Close()

will work normally, but

Code: [Select]

server.Write(...) // disconnect packet
Sleep(1000)
server.Close()

will hang.

I put some more OutputDebugString lines in the wcl library. Here are three different situations...

this is the situation that works as expected.  Close is called immediately after sending the disconnected packet

00000005   3.24970460   [11644] CwclCustomServerConnection::Listen() - top of function   
00000006   22.56838799   [11644] sending disconnect packet   
00000007   22.56859398   [11644] Close() before   
00000008   22.56863403   [11644] CwclCustomServerConnection::Close() - top of function   
00000009   22.56867599   [11644] CwclCustomServerConnection::Disconnect() - top of function   
00000010   22.56877518   [11644] CwclCustomServerConnection::DoDisconnected() - __raise OnDisconnect(this)   
00000011   22.57075119   [11644] WaitForSingleObject before   
00000012   22.57142830   [11644] WaitForSingleObject after   
00000013   22.57195091   [11644] Close() after   
00000014   29.61112595   [11644] CwclCustomClientConnection::Connect() - top of function   
00000015   46.12332916   [11644] WaitForSingleObject before   
00000016   46.12341309   [11644] WaitForSingleObject after   
00000017   48.67276001   [11644] CwclCustomServerConnection::Close() - top of function   


the next situation is calling Close after a 1000ms delay - Close() never returns

00000004   14.85752773   [10868] CwclCustomClientConnection::Connect() - top of function   
00000005   17.82501221   [10868] WaitForSingleObject before   
00000006   17.82562065   [10868] WaitForSingleObject after   
00000007   17.83763504   [10868] CwclCustomServerConnection::Close() - top of function   
00000008   17.83773613   [10868] CwclCustomServerConnection::Listen() - top of function   
00000011   36.43696976   [10868] sending disconnect packet   
00000012   36.99871063   [10868] SendMessage before   
00000013   37.43806076   [10868] Close() before   
00000014   37.43809891   [10868] CwclCustomServerConnection::Close() - top of function   
00000015   37.43815613   [10868] CwclCustomServerConnection::Disconnect() - top of function   
00000016   37.43830872   [10868] CwclCustomServerConnection::DoDisconnected() - __raise OnDisconnect(this)   
00000017   37.43989182   [10868] WaitForSingleObject before   


this situation, we don't call close at all. After the connection is lost, we connect out as a client (which succeeds)


00000004   20.65683746   [25576] CwclCustomClientConnection::Connect() - top of function   
00000005   23.71286583   [25576] WaitForSingleObject before   
00000006   23.71333313   [25576] WaitForSingleObject after   
00000007   23.72513008   [25576] CwclCustomServerConnection::Close() - top of function   
00000008   23.72539139   [25576] CwclCustomServerConnection::Listen() - top of function   
00000011   40.36486053   [25576] sending disconnect packet   
00000012   40.93000793   [25576] SendMessage before   
00000013   51.47891235   [25576] CwclCustomClientConnection::Connect() - top of function   
00000014   51.48120499   [25576] SendMessage after   
00000015   51.50205994   [25576] CwclCustomServerConnection::Disconnect() - top of function   
00000016   51.50217438   [25576] CwclCustomServerConnection::DoDisconnected() - __raise OnDisconnect(this)   
00000017   64.82781219   [25576] WaitForSingleObject before   
00000018   64.82787323   [25576] WaitForSingleObject after   


Cheers
David

[Mike Petrichenko]

Thank you a lot for so detailed log. I am going to find out other way to avoid this deadlock. The problem actualy is in SendMessage(...WIN_SOCK_REINIT). And this SendMessage is really needed and can't be replaced with PostMessage. I think it needs more thread synchronization and at least one flag which shows that remote device trys to disconnect and Close() call shouldn't call disconnect once again. Something like that. I'll prepare update as soon as possible,

[Mike Petrichenko]

Ok, This works:

remove all previouse modifications. Open wclConnections.cpp find void CwclCustomConnection::StopThread() and change

WaitForSingleObject(m_hThread, INFINITE);

to

while (WaitForSingleObject(m_hThread, 200) == WAIT_TIMEOUT)
      wclProcessMessages();

Not so good solution but works. I will keep thinking on it.

[david_dcl]

Hi Mike,

Thanks for that solution. It almost worked, I added one line to it (see below) and then it did work.

Here is the problem (from what I can tell).

If we enter StopThread will the thread is hung in WinSockThread @ line
SendMessage(GetWnd(), WCL_WM_REINIT_MS_BT_SERVER_SOCKET, 0, 0);

the wclProcessMessages() call in your proposed solution will get WinSockThread moving. However, WCL_WM_REINIT_MS_BT_SERVER_SOCKET restarts the thread we are trying to stop, meaning the the SetEvent(m_hThreadEvent) at the top of StopThread is undone.

Adding an extra SetEvent to your solution worked for me.

Code: [Select]

while (WaitForSingleObject(m_hThread, 200) == WAIT_TIMEOUT)
{
   wclProcessMessages();
   SetEvent(m_hThreadEvent);
}

I realise your solution was not meant to be the final one, so I hope the following logs help

with your solution...

00000038        11.30828762     [3028] CwclCustomClientConnection::Connect() - top of function
00000039        11.30886173     [3028] StartThread creating m_hThreadEvent
00000040        14.35457516     [3028] StopThread setting m_hThreadEvent
00000041        14.35502720     [3028] StopThread after WFSO loop
00000042        14.36618328     [3028] CwclCustomServerConnection::Close() - top of function
00000043        14.36636829     [3028] CwclCustomServerConnection::Listen() - top of function
00000044        14.36792374     [3028] StartThread creating m_hThreadEvent
00000045        14.36819744     [3028] WinSockThread before INF wait on m_hThreadEvent & m_hServerEvent
00000046        20.70060539     [3028] WinSockThread after wait
00000047        30.64531136     [3028] sending disconnect packet
00000048        31.19261932     [3028] SendMessage before
00000049        31.51200104     [3028] before close
00000050        31.51218987     [3028] CwclCustomServerConnection::Close() - top of function
00000051        31.51223755     [3028] CwclCustomServerConnection::Disconnect() - top of function
00000052        31.51235962     [3028] CwclCustomServerConnection::DoDisconnected() - __raise OnDisconnect(this)
00000053        31.51367188     [3028] StopThread setting m_hThreadEvent
00000054        31.71428490     [3028] StartThread creating m_hThreadEvent
00000055        31.71444702     [3028] SendMessage after
00000056        31.71450233     [3028] WinSockThread before INF wait on m_hThreadEvent & m_hServerEvent
00000057        31.71455765     [3028] WinSockThread after wait
00000058        31.71479607     [3028] WinSockThread before INF wait on m_hThreadEvent & m_hServerEvent
00000059        31.91424370     [3028] CwclCustomServerConnection::Disconnect() - top of function


with the extra SetEvent()...

00000038        0.18475962      [2984] CwclCustomClientConnection::Connect() - top of function
00000039        0.18550123      [2984] StartThread creating m_hThreadEvent
00000040        3.40439487      [2984] StopThread setting m_hThreadEvent
00000041        3.40490651      [2984] StopThread after WFSO loop
00000042        3.41814327      [2984] CwclCustomServerConnection::Close() - top of function
00000043        3.41825891      [2984] CwclCustomServerConnection::Listen() - top of function
00000044        3.41990399      [2984] StartThread creating m_hThreadEvent
00000045        3.42025471      [2984] WinSockThread before INF wait on m_hThreadEvent & m_hServerEvent
00000046        9.41686344      [2984] WinSockThread after wait
00000047        20.24613571     [2984] sending disconnect packet
00000048        20.80381966     [2984] SendMessage before
00000049        21.09292221     [2984] before close
00000050        21.09298134     [2984] CwclCustomServerConnection::Close() - top of function
00000051        21.09304428     [2984] CwclCustomServerConnection::Disconnect() - top of function
00000052        21.09317398     [2984] CwclCustomServerConnection::DoDisconnected() - __raise OnDisconnect(this)
00000053        21.09450531     [2984] StopThread setting m_hThreadEvent
00000054        21.29557419     [2984] StartThread creating m_hThreadEvent
00000055        21.29578590     [2984] SendMessage after
00000056        21.29583359     [2984] StopThread while loop - setting m_hThreadEvent
00000057        21.29588699     [2984] WinSockThread before INF wait on m_hThreadEvent & m_hServerEvent
00000058        21.29590988     [2984] WinSockThread after wait
00000059        21.29607391     [2984] WinSockThread before INF wait on m_hThreadEvent & m_hServerEvent
00000060        21.29609871     [2984] WinSockThread after wait
00000061        21.29645157     [2984] StopThread after while loop
00000062        21.29689217     [2984] after close

[Mike Petrichenko]

Hi,

Thanks a lot for helping with this problem. Yes, this is not final. I will release much better fix for this issue and let you know.

[Mike Petrichenko]

Hi,

Have sent you an updated fix by e-mail.