View Issue Details

IDProjectCategoryView StatusLast Update
0002935Ham Radio DeluxeBugpublic2019-01-16 22:04
ReporterK7ZCZ 
Assigned ToK7ZCZ 
PrioritynormalSeveritycrashReproducibilityalways
Status closedResolutionfixed 
Product Version6.4.0.896 
Target VersionFixed in Version6.5.0.183 
Summary0002935: Logbook: slow response from HRDInterface() can hang Logbook
DescriptionThe Logbook uses a set of functions called the "HRDInterface" to send commands to, and get status from, the Rig Control application. For example, when clicking on a spot in the DX Cluster list, the Logbook will use these functions to send commands to the radio to change mode and band to the selected spot. The interface implementation is compiled into the HRDInterface001.DLL that ships with the product; the interface definition is in HRDInterface001.H.

If, for any reason, a command takes too long to execute or doesn't give the expected response, code in the Logbook hangs waiting for the response. Looks like it never gives up polling for an answer, but has also changed state so it's not really waiting for an answer.

The issue is exacerbated by the poor design of the HRDInterface API, which returns status as a string (eg, "OK" or "FAILED"). Essentially no code exists that actually tests the result of a command for success or failure, so a change to the sending code which causes a timeout error can't reliably or meaningfully express that state back to the caller. Perhaps the interface is designed to be fire-and-forget and idempotent, but this seems unlikely given the complexity of such design and the quality of the existing code.

Debugging code across the interface is simply impossible, since stopping the command handler in Rig Control causes the logbook to hang. For customers, any event or command which takes too long to execute can cause the Logbook to hang. We see many hangs in attributable to this cause in the Microsoft Developer Dashboard reports.
Steps To ReproduceThere might be a reliable way to repro this issue for end users, but it's a bit dicey because it involves timing of the exeuction of the sent command.

For development, an easy way to repro the issue is to place a breakpoint on any command handler in the Rig Control's RadioViewListener module, then exercise the Logbook to send that command. Spend several seconds with execution stopped at the breakpoint, then resume execution in the debugger. At that point, the Logbook will be hung at the indicated call stack.

Additional Information
     ntdll.dll!_NtWaitForSingleObject@12()	Unknown
     mswsock.dll!SockWaitForSingleObject()	Unknown
     mswsock.dll!_WSPSelect@24()	Unknown
     ws2_32.dll!select()	Unknown
>	HRDInterface001.dll!HRDInterfaceSendMessage(const wchar_t * lpszFormat=0x031d1c1c, ...) Line 625	C++
     HRDLogbook.exe!CDXClusterDlg::SelectSpot() Line 3229	C++
     HRDLogbook.exe!CDXClusterDlg::OnDblclkListSpots(tagNMHDR * pNMHDR=0x04bfed24, long * pResult=0x04bfe92c) Line 2821	C++
     HRDLogbook.exe!_AfxDispatchCmdMsg(CCmdTarget * pTarget=0x0a065258, unsigned int nID=829, int nCode=65533, void (void) * pfn=0x01b6f10b, void * pExtra=0x04bfe734, unsigned int nSig=62, AFX_CMDHANDLERINFO * pHandlerInfo=0x00000000) Line 106	C++
     HRDLogbook.exe!CCmdTarget::OnCmdMsg(unsigned int nID=829, int nCode=65533, void * pExtra=0x04bfe734, AFX_CMDHANDLERINFO * pHandlerInfo=0x00000000) Line 373	C++
     HRDLogbook.exe!CDialog::OnCmdMsg(unsigned int nID=829, int nCode=5177341, void * pExtra=0x04bfe734, AFX_CMDHANDLERINFO * pHandlerInfo=0x00000000) Line 85	C++
     HRDLogbook.exe!CWnd::OnNotify(unsigned int __formal=829, long lParam=79686948, long * pResult=0x04bfe92c) Line 2810	C++
     HRDLogbook.exe!CWnd::OnWndMsg(unsigned int message=78, unsigned int wParam=829, long lParam=79686948, long * pResult=0x04bfe980) Line 2120	C++
     HRDLogbook.exe!CXTPDialogBase<CXTPResizeDialog>::OnWndMsg(unsigned int message=78, unsigned int wParam=829, long lParam=79686948, long * pResult=0x04bfe980) Line 195	C++
     HRDLogbook.exe!CWnd::WindowProc(unsigned int message=78, unsigned int wParam=829, long lParam=79686948) Line 2094	C++
     HRDLogbook.exe!CDXClusterDlg::WindowProc(unsigned int message=78, unsigned int wParam=829, long lParam=79686948) Line 3861	C++
     HRDLogbook.exe!AfxCallWndProc(CWnd * pWnd=0x0a065258, HWND__ * hWnd=0x00c1131c, unsigned int nMsg=78, unsigned int wParam=829, long lParam=79686948) Line 282	C++
     HRDLogbook.exe!AfxWndProc(HWND__ * hWnd=0x00c1131c, unsigned int nMsg=78, unsigned int wParam=829, long lParam=79686948) Line 435	C++
     user32.dll!__InternalCallWinProc@20()	Unknown
     user32.dll!UserCallWinProcCheckWow()	Unknown
     user32.dll!SendMessageWorker()	Unknown
     user32.dll!SendMessageW()	Unknown
     comctl32.dll!CCSendNotify()	Unknown
     comctl32.dll!CLVMouseManager::HandleMouse(int,int,int,unsigned int,int)	Unknown
     comctl32.dll!CListView::WndProc()	Unknown
     comctl32.dll!CListView::s_WndProc()	Unknown
     user32.dll!__InternalCallWinProc@20()	Unknown
     user32.dll!UserCallWinProcCheckWow()	Unknown
     user32.dll!CallWindowProcW()	Unknown
     comctl32.dll!CallNextSubclassProc()	Unknown
     comctl32.dll!CallNextSubclassProc()	Unknown
     comctl32.dll!MasterSubclassProc()	Unknown
     user32.dll!__InternalCallWinProc@20()	Unknown
     user32.dll!UserCallWinProcCheckWow()	Unknown
     user32.dll!CallWindowProcW()	Unknown
     apphelp.dll!DWM8AND16BitHook_CallWindowProcW(long (*)(struct HWND__ *,unsigned int,unsigned int,long),struct HWND__ *,unsigned int,unsigned int,long)	Unknown
     HRDLogbook.exe!CWnd::DefWindowProcW(unsigned int nMsg=515, unsigned int wParam=1, long lParam=10355188) Line 1110	C++
     HRDLogbook.exe!CWnd::WindowProc(unsigned int message=515, unsigned int wParam=1, long lParam=10355188) Line 2095	C++
     HRDLogbook.exe!AfxCallWndProc(CWnd * pWnd=0x0a0655d8, HWND__ * hWnd=0x00530cde, unsigned int nMsg=515, unsigned int wParam=1, long lParam=10355188) Line 282	C++
     HRDLogbook.exe!AfxWndProc(HWND__ * hWnd=0x00530cde, unsigned int nMsg=515, unsigned int wParam=1, long lParam=10355188) Line 435	C++
     user32.dll!__InternalCallWinProc@20()	Unknown
     user32.dll!UserCallWinProcCheckWow()	Unknown
     user32.dll!DispatchMessageWorker()	Unknown
     user32.dll!IsDialogMessageW()	Unknown
     HRDLogbook.exe!CWnd::IsDialogMessageW(tagMSG * lpMsg=0x000f3d58) Line 193	C++
     HRDLogbook.exe!CWnd::PreTranslateInput(tagMSG * lpMsg=0x000f3d58) Line 4590	C++
     HRDLogbook.exe!CDialog::PreTranslateMessage(tagMSG * pMsg=0x000f3d58) Line 80	C++
     HRDLogbook.exe!CXTPDialogBase<CXTPResizeDialog>::PreTranslateMessage(tagMSG * pMsg=0x000f3d58) Line 183	C++
     HRDLogbook.exe!CWnd::WalkPreTranslateTree(HWND__ * hWndStop=0x00dc0b24, tagMSG * pMsg=0x000f3d58) Line 3363	C++
     HRDLogbook.exe!AfxInternalPreTranslateMessage(tagMSG * pMsg=0x000f3d58) Line 233	C++
     HRDLogbook.exe!CWinThread::PreTranslateMessage(tagMSG * pMsg=0x000f3d58) Line 777	C++
     HRDLogbook.exe!CHRDLogbookApp::PreTranslateMessage(tagMSG * pMsg=0x000f3d58) Line 1495	C++
     HRDLogbook.exe!AfxPreTranslateMessage(tagMSG * pMsg=0x000f3d58) Line 252	C++
     HRDLogbook.exe!AfxInternalPumpMessage() Line 178	C++
     HRDLogbook.exe!CWinThread::PumpMessage() Line 900	C++
     HRDLogbook.exe!CWinThread::Run() Line 629	C++
     HRDLogbook.exe!CWinApp::Run() Line 787	C++
     HRDLogbook.exe!AfxWinMain(HINSTANCE__ * hInstance=0x01120000, HINSTANCE__ * hPrevInstance=0x00000000, wchar_t * lpCmdLine=0x000e3400, int nCmdShow=10) Line 47	C++
     HRDLogbook.exe!wWinMain(HINSTANCE__ * hInstance=0x01120000, HINSTANCE__ * hPrevInstance=0x00000000, wchar_t * lpCmdLine=0x000e3400, int nCmdShow=10) Line 26	C++
     HRDLogbook.exe!__tmainCRTStartup() Line 251	C
     HRDLogbook.exe!wWinMainCRTStartup() Line 165	C
     kernel32.dll!@BaseThreadInitThunk@12()	Unknown
     ntdll.dll!__RtlUserThreadStart()	Unknown
     ntdll.dll!__RtlUserThreadStart@8()	Unknown
TagsNo tags attached.
ModuleLogbook
Sub-ModuleInterfacing
Testing Not Tested

Relationships

Activities

K7ZCZ

2018-12-10 12:46

manager   ~0006566

Fixed with this checkin:
https://hrdsoftware.visualstudio.com/HRD/_versionControl/changeset/4535

WA9PIE

2018-12-11 01:14

administrator   ~0006573

I updated FIV to 6.5.0.132 on assumption.

WA9PIE

2018-12-21 01:05

administrator   ~0006763

I'm going to accept this as valid due to the level of difficulty with the end-user repro steps.

Issue History

Date Modified Username Field Change
2018-11-05 16:22 K7ZCZ New Issue
2018-11-05 16:22 K7ZCZ Assigned To => K7ZCZ
2018-11-05 16:22 K7ZCZ Status new => assigned
2018-12-10 12:46 K7ZCZ Status assigned => resolved
2018-12-10 12:46 K7ZCZ Resolution open => fixed
2018-12-10 12:46 K7ZCZ Note Added: 0006566
2018-12-11 01:14 WA9PIE Fixed in Version => 6.5.0.132
2018-12-11 01:14 WA9PIE Steps to Reproduce Updated View Revisions
2018-12-11 01:14 WA9PIE Additional Information Updated View Revisions
2018-12-11 01:14 WA9PIE Note Added: 0006573
2018-12-21 01:05 WA9PIE Status resolved => closed
2018-12-21 01:05 WA9PIE Testing Not Started => Not Tested
2018-12-21 01:05 WA9PIE Note Added: 0006763
2019-01-16 22:04 WA9PIE Fixed in Version 6.5.0.132 => 6.5.0.183
2019-01-16 22:04 WA9PIE Project 3 - Current Dev List => Ham Radio Deluxe