diff --git a/CMakeLists.txt b/CMakeLists.txt index d5fbd496..645d6d18 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -15,6 +15,7 @@ add_compile_options(/Zc:__cplusplus) # add_definitions( # /DFANY_DEBUG=1 +# /DFANY_IPC_DEBUG=1 # ) # fmt @@ -165,4 +166,4 @@ add_library(${PROJECT_NAME} SHARED "./src/Server.cpp" ) -target_link_libraries(${PROJECT_NAME} PRIVATE fmt::fmt-header-only) \ No newline at end of file +target_link_libraries(${PROJECT_NAME} PRIVATE fmt::fmt-header-only) diff --git a/src/IME/MetasequoiaIME.cpp b/src/IME/MetasequoiaIME.cpp index e40a2aba..87e1fd5d 100644 --- a/src/IME/MetasequoiaIME.cpp +++ b/src/IME/MetasequoiaIME.cpp @@ -17,6 +17,14 @@ #include "Global/FanyDefines.h" #include "Utils/FanyUtils.h" +#ifdef FANY_IPC_DEBUG +#define FANY_IPC_LOG_RAW(message) OutputDebugString(message) +#define FANY_IPC_LOGF(...) OutputDebugString(fmt::format(__VA_ARGS__).c_str()) +#else +#define FANY_IPC_LOG_RAW(message) ((void)0) +#define FANY_IPC_LOGF(...) ((void)0) +#endif + #pragma comment(lib, "Shcore.lib") namespace @@ -693,6 +701,7 @@ LRESULT CALLBACK CMetasequoiaIME_WindowProc(HWND hWnd, UINT message, WPARAM wPar #ifdef FANY_DEBUG OutputDebugString(fmt::format(L"[msime]: Try to connect named pipe via WM_ConnectNamedpipe").c_str()); #endif + FANY_IPC_LOG_RAW(L"[msime]: [ipc] WM_ConnectNamedpipe: start reconnect-all sequence"); KillTimer(hWnd, TIMER_CONNECT_ALL_NAMEDPIPE); g_connectAllNamedpipeRetryCount = 0; SendToAuxNamedpipe(L"kill"); @@ -704,6 +713,7 @@ LRESULT CALLBACK CMetasequoiaIME_WindowProc(HWND hWnd, UINT message, WPARAM wPar #ifdef FANY_DEBUG OutputDebugString(fmt::format(L"[msime]: WM_DisconnectNamedpipe.").c_str()); #endif + FANY_IPC_LOG_RAW(L"[msime]: [ipc] WM_DisconnectNamedpipe: closing all client pipe handles"); KillTimer(hWnd, TIMER_CONNECT_ALL_NAMEDPIPE); KillTimer(hWnd, TIMER_CONNECT_TO_TSF_NAMEDPIPE); g_connectAllNamedpipeRetryCount = 0; @@ -715,6 +725,7 @@ LRESULT CALLBACK CMetasequoiaIME_WindowProc(HWND hWnd, UINT message, WPARAM wPar #ifdef FANY_DEBUG OutputDebugString(fmt::format(L"[msime]: Try to Connect to TSF named pipe").c_str()); #endif + FANY_IPC_LOG_RAW(L"[msime]: [ipc] WM_ConnectToTsfNamedpipe: start reconnect-to-tsf sequence"); KillTimer(hWnd, TIMER_CONNECT_TO_TSF_NAMEDPIPE); g_connectToTsfNamedpipeRetryCount = 0; // Keep old behavior: wait once before first connect try, but do it asynchronously. @@ -727,6 +738,7 @@ LRESULT CALLBACK CMetasequoiaIME_WindowProc(HWND hWnd, UINT message, WPARAM wPar // 如果用户已经切换走了,就不用继续重试 if (!Global::g_connected) { + FANY_IPC_LOG_RAW(L"[msime]: [ipc] reconnect-all aborted because threadmgr is disconnected"); KillTimer(hWnd, TIMER_CONNECT_ALL_NAMEDPIPE); g_connectAllNamedpipeRetryCount = 0; break; @@ -740,6 +752,7 @@ LRESULT CALLBACK CMetasequoiaIME_WindowProc(HWND hWnd, UINT message, WPARAM wPar { KillTimer(hWnd, TIMER_CONNECT_ALL_NAMEDPIPE); g_connectAllNamedpipeRetryCount = 0; + FANY_IPC_LOG_RAW(L"[msime]: [ipc] reconnect-all succeeded"); #ifdef FANY_DEBUG OutputDebugString(fmt::format(L"[msime]: Yes Connected to named pipe :)").c_str()); #endif @@ -749,6 +762,7 @@ LRESULT CALLBACK CMetasequoiaIME_WindowProc(HWND hWnd, UINT message, WPARAM wPar g_connectAllNamedpipeRetryCount++; if (g_connectAllNamedpipeRetryCount >= CONNECT_ALL_NAMEDPIPE_MAX_RETRY) { + FANY_IPC_LOG_RAW(L"[msime]: [ipc] reconnect-all reached max retry count"); KillTimer(hWnd, TIMER_CONNECT_ALL_NAMEDPIPE); g_connectAllNamedpipeRetryCount = 0; } @@ -766,12 +780,14 @@ LRESULT CALLBACK CMetasequoiaIME_WindowProc(HWND hWnd, UINT message, WPARAM wPar { KillTimer(hWnd, TIMER_CONNECT_TO_TSF_NAMEDPIPE); g_connectToTsfNamedpipeRetryCount = 0; + FANY_IPC_LOG_RAW(L"[msime]: [ipc] reconnect-to-tsf succeeded"); break; } g_connectToTsfNamedpipeRetryCount++; if (g_connectToTsfNamedpipeRetryCount >= CONNECT_TO_TSF_NAMEDPIPE_MAX_RETRY) { + FANY_IPC_LOG_RAW(L"[msime]: [ipc] reconnect-to-tsf reached max retry count"); KillTimer(hWnd, TIMER_CONNECT_TO_TSF_NAMEDPIPE); g_connectToTsfNamedpipeRetryCount = 0; } diff --git a/src/IPC/Ipc.cpp b/src/IPC/Ipc.cpp index dbc80ba9..e8f16109 100644 --- a/src/IPC/Ipc.cpp +++ b/src/IPC/Ipc.cpp @@ -10,6 +10,16 @@ #include "MetasequoiaIME.h" #include +#ifdef FANY_IPC_DEBUG +#define FANY_IPC_LOG_RAW(message) OutputDebugString(message) +#define FANY_IPC_LOGW(message) OutputDebugString((message).c_str()) +#define FANY_IPC_LOGF(...) OutputDebugString(fmt::format(__VA_ARGS__).c_str()) +#else +#define FANY_IPC_LOG_RAW(message) ((void)0) +#define FANY_IPC_LOGW(message) ((void)0) +#define FANY_IPC_LOGF(...) ((void)0) +#endif + static HANDLE hMapFile = nullptr; static void *pBuf; static FanyImeSharedMemoryData *sharedData; @@ -31,6 +41,38 @@ inline bool IsValidPipeHandle(HANDLE hPipeHandle) return hPipeHandle != nullptr && hPipeHandle != INVALID_HANDLE_VALUE; } +void LogCreateFileFailure(const wchar_t *pipeName) +{ + FANY_IPC_LOGF(L"[msime]: [ipc] CreateFile failed: pipe={}, gle={}", pipeName, GetLastError()); +} + +void LogCreateFileSuccess(const wchar_t *pipeName) +{ + FANY_IPC_LOGF(L"[msime]: [ipc] CreateFile connected: pipe={}", pipeName); +} + +void LogWriteFailure(const wchar_t *pipeName, DWORD bytesWritten, DWORD expectedBytes) +{ + FANY_IPC_LOGF(L"[msime]: [ipc] WriteFile failed: pipe={}, gle={}, bytes_written={}, expected_bytes={}", pipeName, + GetLastError(), bytesWritten, expectedBytes); +} + +void LogReadFailure(const wchar_t *pipeName, DWORD bytesRead) +{ + FANY_IPC_LOGF(L"[msime]: [ipc] ReadFile failed or empty: pipe={}, gle={}, bytes_read={}", pipeName, + GetLastError(), bytesRead); +} + +void LogPeekFailure(const wchar_t *pipeName) +{ + FANY_IPC_LOGF(L"[msime]: [ipc] PeekNamedPipe failed: pipe={}, gle={}", pipeName, GetLastError()); +} + +void LogAuxMessage(const std::wstring &message) +{ + FANY_IPC_LOGF(L"[msime]: [ipc] SendToAuxNamedpipe: {}", message); +} + void ClosePipeHandleIfValid(HANDLE &hPipeHandle) { if (IsValidPipeHandle(hPipeHandle)) @@ -59,10 +101,12 @@ bool TryOpenClientPipe(HANDLE &hPipeHandle, const wchar_t *pipeName) if (openedPipe == INVALID_HANDLE_VALUE) { + LogCreateFileFailure(pipeName); return false; } hPipeHandle = openedPipe; + LogCreateFileSuccess(pipeName); return true; } } // namespace @@ -438,12 +482,12 @@ void SendToNamedpipe() if (hPipe == INVALID_HANDLE_VALUE) { - // TODO: Log + LogCreateFileFailure(FANY_IME_NAMED_PIPE); return; } else { - // TODO: Log + LogCreateFileSuccess(FANY_IME_NAMED_PIPE); } } @@ -459,6 +503,7 @@ void SendToNamedpipe() { /* Error handling: 必须将 hPipe 置为无效,否则将留下脏句柄,导致有些情况下无法再次连接 */ DWORD err = GetLastError(); + LogWriteFailure(FANY_IME_NAMED_PIPE, bytesWritten, sizeof(namedpipeData)); // if (err == ERROR_BROKEN_PIPE || err == ERROR_NO_DATA) // { /* 将两个方向的管道同时置为无效 */ @@ -499,7 +544,7 @@ void SendToNamedpipe() if (hPipe == INVALID_HANDLE_VALUE) { -// TODO: Log + LogCreateFileFailure(FANY_IME_NAMED_PIPE); #ifdef FANY_DEBUG OutputDebugString(fmt::format(L"[msime]: SendToNamedpipe failed eventually02.").c_str()); #endif @@ -507,7 +552,7 @@ void SendToNamedpipe() } else { - // TODO: Log + LogCreateFileSuccess(FANY_IME_NAMED_PIPE); } DWORD bytesWritten = 0; @@ -521,7 +566,7 @@ void SendToNamedpipe() if (!ret || bytesWritten != sizeof(namedpipeData)) { -// TODO: Error handling + LogWriteFailure(FANY_IME_NAMED_PIPE, bytesWritten, sizeof(namedpipeData)); #ifdef FANY_DEBUG OutputDebugString(fmt::format(L"[msime]: SendToNamedpipe failed eventually03.").c_str()); #endif @@ -560,12 +605,12 @@ void ClearNamedpipeDataIfExists() ); if (hFromServerPipe == INVALID_HANDLE_VALUE) { - // TODO: Log + LogCreateFileFailure(FANY_IME_TO_TSF_NAMED_PIPE); return; } else { - // TODO: Log + LogCreateFileSuccess(FANY_IME_TO_TSF_NAMED_PIPE); } } @@ -584,6 +629,10 @@ void ClearNamedpipeDataIfExists() if (!peekOk || bytesAvailable == 0) { + if (!peekOk) + { + LogPeekFailure(FANY_IME_TO_TSF_NAMED_PIPE); + } break; // no more data or pipe error } @@ -597,6 +646,7 @@ void ClearNamedpipeDataIfExists() if (!readOk || bytesRead == 0) { + LogReadFailure(FANY_IME_TO_TSF_NAMED_PIPE, bytesRead); break; } } @@ -626,7 +676,7 @@ struct FanyImeNamedpipeDataToTsf *TryReadDataFromServerPipeWithTimeout() ); if (hFromServerPipe == INVALID_HANDLE_VALUE) { - // TODO: Log + LogCreateFileFailure(FANY_IME_TO_TSF_NAMED_PIPE); namedpipeDataFromServer.msg_type = Global::DataFromServerMsgType::Normal; // wcscpy_s(namedpipeDataFromServer.candidate_string, L"PipeOpenError"); wcscpy_s(namedpipeDataFromServer.candidate_string, L"X"); @@ -634,7 +684,7 @@ struct FanyImeNamedpipeDataToTsf *TryReadDataFromServerPipeWithTimeout() } else { - // TODO: Log + LogCreateFileSuccess(FANY_IME_TO_TSF_NAMED_PIPE); } } @@ -661,6 +711,7 @@ struct FanyImeNamedpipeDataToTsf *TryReadDataFromServerPipeWithTimeout() /* Error handling: 必须将 hFromServerPipe 置为无效,否则将留下脏句柄,导致有些情况下无法再次连接 */ CloseHandle(hFromServerPipe); hFromServerPipe = INVALID_HANDLE_VALUE; + FANY_IPC_LOGF(L"[msime]: [ipc] TryReadDataFromServerPipeWithTimeout timeout after {} ms", timeoutMs); namedpipeDataFromServer.msg_type = Global::DataFromServerMsgType::Normal; // Pipe timeout error @@ -690,7 +741,7 @@ struct FanyImeNamedpipeDataToTsf *ReadDataFromServerViaNamedPipe() ); if (hFromServerPipe == INVALID_HANDLE_VALUE) { - // TODO: Log + LogCreateFileFailure(FANY_IME_TO_TSF_NAMED_PIPE); namedpipeDataFromServer.msg_type = 0; // wcscpy_s(namedpipeDataFromServer.candidate_string, L"PipeOpenError"); wcscpy_s(namedpipeDataFromServer.candidate_string, L"X"); @@ -698,7 +749,7 @@ struct FanyImeNamedpipeDataToTsf *ReadDataFromServerViaNamedPipe() } else { - // TODO: Log + LogCreateFileSuccess(FANY_IME_TO_TSF_NAMED_PIPE); } } @@ -712,7 +763,7 @@ struct FanyImeNamedpipeDataToTsf *ReadDataFromServerViaNamedPipe() ); if (!readResult || bytesRead == 0) // Disconnected or error { - // TODO: Log + LogReadFailure(FANY_IME_TO_TSF_NAMED_PIPE, bytesRead); } else { @@ -764,8 +815,10 @@ void SendToAuxNamedpipe(std::wstring pipeData) #ifdef FANY_DEBUG OutputDebugString(fmt::format(L"[msime]: SendToAuxNamedpipe: PipeOpenError: {}", pipeData).c_str()); #endif + LogCreateFileFailure(FANY_IME_AUX_NAMED_PIPE); return; } + LogAuxMessage(pipeData); DWORD bytesWritten = 0; BOOL ret = WriteFile( // hAuxPipe, // @@ -776,7 +829,7 @@ void SendToAuxNamedpipe(std::wstring pipeData) ); if (!ret || bytesWritten != pipeData.length() * sizeof(wchar_t)) { - // TODO: Error handling + LogWriteFailure(FANY_IME_AUX_NAMED_PIPE, bytesWritten, pipeData.length() * sizeof(wchar_t)); } CloseHandle(hAuxPipe); }