Wireless Communication Library Support Forum
Frameworks => Bluetooth Framework => Topic started by: david_dcl on April 08, 2014, 07:08:06 AM
-
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
-
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).
-
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
-
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.
-
in wclServers.cpp find
void CwclCustomServerConnection::WinSockThread()
routine. Find
if (GetTransport() == trBluetooth)
SendMessage(GetWnd(), WCL_WM_REINIT_MS_BT_SERVER_SOCKET, 0, 0);
lines there and change
if (GetTransport() == trBluetooth)
to
if (GetTransport() == trBluetooth && m_State == ssConnected)
This should fix the issue. Please, let me know if it does or does not.
-
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.
server.Write(...) // disconnect packet
server.Close()
will work normally, but
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
-
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,
-
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.
-
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.
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
-
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.
-
Hi,
Have sent you an updated fix by e-mail.