[Spice-commits] 3 commits - common/vdlog.cpp common/vdlog.h vdagent/vdagent.cpp vdservice/vdservice.cpp
Arnon Gilboa
agilboa at kemper.freedesktop.org
Wed Nov 23 01:34:54 PST 2011
common/vdlog.cpp | 4 --
common/vdlog.h | 62 ++++++++++++++++++++++++++--------
vdagent/vdagent.cpp | 86 ++++++++++++++++++++++++++++++++++++------------
vdservice/vdservice.cpp | 68 ++++++++++++++++++++++---------------
4 files changed, 152 insertions(+), 68 deletions(-)
New commits:
commit 017482d779ed087326f40d6379a990de5d65234d
Author: Arnon Gilboa <agilboa at redhat.com>
Date: Mon Nov 21 09:48:50 2011 +0200
vdlog: change log times to human readable date & time rhbz#672828
-use RHEV log format
-add log levels & macros
-remove LOG_ENABLED ifdefs
diff --git a/common/vdlog.cpp b/common/vdlog.cpp
index 1001de3..8ece384 100644
--- a/common/vdlog.cpp
+++ b/common/vdlog.cpp
@@ -40,7 +40,6 @@ VDLog::~VDLog()
VDLog* VDLog::get(TCHAR* path)
{
-#ifdef LOG_ENABLED
if (_log || !path) {
return _log;
}
@@ -64,9 +63,6 @@ VDLog* VDLog::get(TCHAR* path)
}
_log = new VDLog(handle);
return _log;
-#else
- return NULL;
-#endif
}
void VDLog::printf(const char* format, ...)
diff --git a/common/vdlog.h b/common/vdlog.h
index bb2eb28..5a794b6 100644
--- a/common/vdlog.h
+++ b/common/vdlog.h
@@ -22,8 +22,8 @@
#include <tchar.h>
#include <crtdbg.h>
#include <windows.h>
-
-#define LOG_ENABLED
+#include <time.h>
+#include <sys/timeb.h>
class VDLog {
public:
@@ -39,23 +39,55 @@ private:
FILE* _handle;
};
-#ifdef LOG_ENABLED
-#define vd_printf(format, ...) { \
- VDLog* log = VDLog::get(); \
- double secs = GetTickCount() / 1000.0; \
- if (log) { \
- log->printf("%.3f %s: " format "\n", secs, __FUNCTION__, __VA_ARGS__); \
- } else { \
- printf("%.3f %s: " format "\n", secs, __FUNCTION__, __VA_ARGS__); \
- } \
-}
+enum {
+ LOG_DEBUG,
+ LOG_INFO,
+ LOG_WARN,
+ LOG_ERROR,
+ LOG_FATAL
+};
-#define ASSERT(x) _ASSERTE(x)
+#ifdef _DEBUG
+static unsigned int log_level = LOG_DEBUG;
#else
-#define vd_printf(format, ...)
-#define ASSERT(x)
+static unsigned int log_level = LOG_INFO;
#endif
+#define PRINT_LINE(type, format, datetime, ms, ...) \
+ printf("%u::%s::%s,%.3d::%s::" format "\n", GetCurrentThreadId(), type, datetime, ms, \
+ __FUNCTION__, ## __VA_ARGS__);
+
+#define LOG(type, format, ...) if (type >= log_level && type <= LOG_FATAL) { \
+ VDLog* log = VDLog::get(); \
+ const char *type_as_char[] = { "DEBUG", "INFO", "WARN", "ERROR", "FATAL" }; \
+ struct _timeb now; \
+ struct tm today; \
+ char datetime_str[20]; \
+ _ftime_s(&now); \
+ localtime_s(&today, &now.time); \
+ strftime(datetime_str, 20, "%Y-%m-%d %H:%M:%S", &today); \
+ if (log) { \
+ log->PRINT_LINE(type_as_char[type], format, datetime_str, now.millitm, ## __VA_ARGS__); \
+ } else { \
+ PRINT_LINE(type_as_char[type], format, datetime_str, now.millitm, ## __VA_ARGS__); \
+ } \
+}
+
+#define vd_printf(format, ...) LOG(LOG_INFO, format, ## __VA_ARGS__)
+#define LOG_INFO(format, ...) LOG(LOG_INFO, format, ## __VA_ARGS__)
+#define LOG_WARN(format, ...) LOG(LOG_WARN, format, ## __VA_ARGS__)
+#define LOG_ERROR(format, ...) LOG(LOG_ERROR, format, ## __VA_ARGS__)
+
+#define DBGLEVEL 1000
+
+#define DBG(level, format, ...) { \
+ if (level <= DBGLEVEL) { \
+ LOG(LOG_DEBUG, format, ## __VA_ARGS__); \
+ } \
+}
+
+#define ASSERT(x) _ASSERTE(x)
+
void log_version();
#endif
commit 28d7028278f8ca061c6dee9934901eaa035ef7bb
Author: Arnon Gilboa <agilboa at redhat.com>
Date: Wed Nov 16 12:09:46 2011 +0200
vdagent: release clipboard ownership on agent stop & desktop switch rhbz#731628
-use event queue for agent stop & desktop switch
-exit gracefully on session end
diff --git a/vdagent/vdagent.cpp b/vdagent/vdagent.cpp
index 646afed..f0f5243 100644
--- a/vdagent/vdagent.cpp
+++ b/vdagent/vdagent.cpp
@@ -20,6 +20,7 @@
#include "display_setting.h"
#include "ximage.h"
#include <lmcons.h>
+#include <queue>
#include <set>
#define VD_AGENT_LOG_PATH TEXT("%svdagent.log")
@@ -88,6 +89,9 @@ private:
DWORD get_cximage_format(uint32_t type);
enum { owner_none, owner_guest, owner_client };
void set_clipboard_owner(int new_owner);
+ enum { CONTROL_STOP, CONTROL_DESKTOP_SWITCH };
+ void set_control_event(int control_command);
+ void handle_control_event();
uint8_t* write_lock(DWORD bytes = 0);
void write_unlock(DWORD bytes = 0);
bool write_message(uint32_t type, uint32_t size, void* data);
@@ -109,7 +113,7 @@ private:
LONG _mouse_y;
INPUT _input;
DWORD _input_time;
- HANDLE _desktop_switch_event;
+ HANDLE _control_event;
HANDLE _clipboard_event;
VDAgentMessage* _in_msg;
uint32_t _in_msg_pos;
@@ -119,10 +123,13 @@ private:
bool _pending_input;
bool _pending_write;
bool _running;
+ bool _desktop_switch;
DesktopLayout* _desktop_layout;
DisplaySetting _display_setting;
VDPipeState _pipe_state;
mutex_t _write_mutex;
+ mutex_t _control_mutex;
+ std::queue<int> _control_queue;
bool _logon_desktop;
bool _display_setting_initialized;
@@ -154,7 +161,7 @@ VDAgent::VDAgent()
, _mouse_x (0)
, _mouse_y (0)
, _input_time (0)
- , _desktop_switch_event (NULL)
+ , _control_event (NULL)
, _clipboard_event (NULL)
, _in_msg (NULL)
, _in_msg_pos (0)
@@ -164,6 +171,7 @@ VDAgent::VDAgent()
, _pending_input (false)
, _pending_write (false)
, _running (false)
+ , _desktop_switch (false)
, _desktop_layout (NULL)
, _display_setting (VD_AGENT_REGISTRY_KEY)
, _logon_desktop (false)
@@ -182,6 +190,7 @@ VDAgent::VDAgent()
ZeroMemory(&_input, sizeof(INPUT));
ZeroMemory(&_pipe_state, sizeof(VDPipeState));
MUTEX_INIT(_write_mutex);
+ MUTEX_INIT(_control_mutex);
_singleton = this;
}
@@ -203,7 +212,7 @@ DWORD WINAPI VDAgent::event_thread_proc(LPVOID param)
DWORD wait_ret = WaitForSingleObject(desktop_event, INFINITE);
switch (wait_ret) {
case WAIT_OBJECT_0:
- SetEvent((HANDLE)param);
+ _singleton->set_control_event(CONTROL_DESKTOP_SWITCH);
break;
case WAIT_TIMEOUT:
default:
@@ -233,9 +242,9 @@ bool VDAgent::run()
if (!SetProcessShutdownParameters(0x100, 0)) {
vd_printf("SetProcessShutdownParameters failed %u", GetLastError());
}
- _desktop_switch_event = CreateEvent(NULL, FALSE, FALSE, NULL);
+ _control_event = CreateEvent(NULL, FALSE, FALSE, NULL);
_clipboard_event = CreateEvent(NULL, FALSE, FALSE, NULL);
- if (!_desktop_switch_event || !_clipboard_event) {
+ if (!_control_event || !_clipboard_event) {
vd_printf("CreateEvent() failed: %d", GetLastError());
cleanup();
return false;
@@ -257,8 +266,7 @@ bool VDAgent::run()
return false;
}
_running = true;
- event_thread = CreateThread(NULL, 0, event_thread_proc, _desktop_switch_event, 0,
- &event_thread_id);
+ event_thread = CreateThread(NULL, 0, event_thread_proc, NULL, 0, &event_thread_id);
if (!event_thread) {
vd_printf("CreateThread() failed: %d", GetLastError());
cleanup();
@@ -268,6 +276,9 @@ bool VDAgent::run()
read_completion(0, 0, &_pipe_state.read.overlap);
while (_running) {
input_desktop_message_loop();
+ if (_clipboard_owner == owner_guest) {
+ set_clipboard_owner(owner_none);
+ }
}
vd_printf("Agent stopped");
CloseHandle(event_thread);
@@ -277,15 +288,45 @@ bool VDAgent::run()
void VDAgent::cleanup()
{
- CloseHandle(_desktop_switch_event);
+ CloseHandle(_control_event);
CloseHandle(_clipboard_event);
CloseHandle(_pipe_state.pipe);
delete _desktop_layout;
}
+void VDAgent::set_control_event(int control_command)
+{
+ MUTEX_LOCK(_control_mutex);
+ _control_queue.push(control_command);
+ if (_control_event && !SetEvent(_control_event)) {
+ vd_printf("SetEvent() failed: %u", GetLastError());
+ }
+ MUTEX_UNLOCK(_control_mutex);
+}
+
+void VDAgent::handle_control_event()
+{
+ MUTEX_LOCK(_control_mutex);
+ while (_control_queue.size()) {
+ int control_command = _control_queue.front();
+ _control_queue.pop();
+ vd_printf("Control command %d", control_command);
+ switch (control_command) {
+ case CONTROL_STOP:
+ _running = false;
+ break;
+ case CONTROL_DESKTOP_SWITCH:
+ _desktop_switch = true;
+ break;
+ default:
+ vd_printf("Unsupported control command %u", control_command);
+ }
+ }
+ MUTEX_UNLOCK(_control_mutex);
+}
+
void VDAgent::input_desktop_message_loop()
{
- bool desktop_switch = false;
TCHAR desktop_name[MAX_PATH];
DWORD wait_ret;
HDESK hdesk;
@@ -333,13 +374,12 @@ void VDAgent::input_desktop_message_loop()
return;
}
_hwnd_next_viewer = SetClipboardViewer(_hwnd);
- while (_running && !desktop_switch) {
- wait_ret = MsgWaitForMultipleObjectsEx(1, &_desktop_switch_event, INFINITE, QS_ALLINPUT,
+ while (_running && !_desktop_switch) {
+ wait_ret = MsgWaitForMultipleObjectsEx(1, &_control_event, INFINITE, QS_ALLINPUT,
MWMO_ALERTABLE);
switch (wait_ret) {
case WAIT_OBJECT_0:
- vd_printf("WinSta0_DesktopSwitch");
- desktop_switch = true;
+ handle_control_event();
break;
case WAIT_OBJECT_0 + 1:
while (PeekMessage(&msg, NULL, 0, 0, PM_REMOVE)) {
@@ -354,6 +394,7 @@ void VDAgent::input_desktop_message_loop()
vd_printf("MsgWaitForMultipleObjectsEx(): %u", wait_ret);
}
}
+ _desktop_switch = false;
if (_pending_input) {
KillTimer(_hwnd, VD_TIMER_ID);
_pending_input = false;
@@ -901,7 +942,7 @@ bool VDAgent::handle_clipboard_grab(VDAgentClipboardGrab* clipboard_grab, uint32
_grab_types.clear();
for (uint32_t i = 0; i < size / sizeof(clipboard_grab->types[0]); i++) {
- vd_printf("grab %u", clipboard_grab->types[i]);
+ vd_printf("grab type %u", clipboard_grab->types[i]);
uint32_t format = get_clipboard_format(clipboard_grab->types[i]);
//On first supported type, open and empty the clipboard
if (format && grab_formats.empty()) {
@@ -1154,7 +1195,7 @@ VOID CALLBACK VDAgent::read_completion(DWORD err, DWORD bytes, LPOVERLAPPED over
return;
}
if (err) {
- vd_printf("error %u", err);
+ vd_printf("vdservice disconnected (%u)", err);
a->_running = false;
return;
}
@@ -1225,7 +1266,7 @@ VOID CALLBACK VDAgent::write_completion(DWORD err, DWORD bytes, LPOVERLAPPED ove
return;
}
if (err) {
- vd_printf("error %u", err);
+ vd_printf("vdservice disconnected (%u)", err);
a->_running = false;
return;
}
@@ -1297,11 +1338,14 @@ LRESULT CALLBACK VDAgent::wnd_proc(HWND hwnd, UINT message, WPARAM wparam, LPARA
case WM_RENDERFORMAT:
a->on_clipboard_request((UINT)wparam);
break;
- case WM_RENDERALLFORMATS:
- vd_printf("WM_RENDERALLFORMATS");
- break;
- case WM_DESTROYCLIPBOARD:
- vd_printf("WM_DESTROYCLIPBOARD");
+ case WM_ENDSESSION:
+ if (wparam) {
+ vd_printf("Session ended");
+ if (a->_clipboard_owner == owner_guest) {
+ a->set_clipboard_owner(owner_none);
+ }
+ a->set_control_event(CONTROL_STOP);
+ }
break;
default:
return DefWindowProc(hwnd, message, wparam, lparam);
commit 5ffb111944108af7d1279044a57a8f225846adfd
Author: Arnon Gilboa <agilboa at redhat.com>
Date: Wed Nov 16 12:03:21 2011 +0200
vdservice: fix vdagent connection & termination handling rhbz#750037
-extend vdagent wait timeouts
-timeout occured when connecting during windows startup, using wan emulator with
1Mbps bandwith, and only when qxl driver is installed. It might be due to spice
commands window control which in this case indirectly affects windows startup
timings (needs further investigation).
-fix wait for vdagent connect
-fix wait for vdagent termination & exit code handling
-cleanup & nicify relevant logs while debugging
diff --git a/vdservice/vdservice.cpp b/vdservice/vdservice.cpp
index b382a6e..beb1fe3 100644
--- a/vdservice/vdservice.cpp
+++ b/vdservice/vdservice.cpp
@@ -34,7 +34,7 @@
#define VD_SERVICE_LOG_PATH TEXT("%svdservice.log")
#define VD_SERVICE_LOAD_ORDER_GROUP TEXT("Pointer Port")
#define VD_AGENT_PATH TEXT("%s\\vdagent.exe")
-#define VD_AGENT_TIMEOUT 3000
+#define VD_AGENT_TIMEOUT 10000
#define VD_AGENT_MAX_RESTARTS 10
#define VD_AGENT_RESTART_INTERVAL 3000
#define VD_AGENT_RESTART_COUNT_RESET_INTERVAL 60000
@@ -84,6 +84,7 @@ private:
void set_control_event(int control_command);
void handle_control_event();
void pipe_write_completion();
+ void pipe_read_completion();
void write_agent_control(uint32_t type, uint32_t opaque);
void read_pipe();
void handle_pipe_data(DWORD bytes);
@@ -336,7 +337,6 @@ void VDService::handle_control_event()
}
}
MUTEX_UNLOCK(_control_mutex);
-
}
DWORD WINAPI VDService::control_handler(DWORD control, DWORD event_type, LPVOID event_data,
@@ -517,7 +517,6 @@ bool VDService::execute()
_events[VD_EVENT_PIPE_READ] = _pipe_state.read.overlap.hEvent;
_events[VD_EVENT_PIPE_WRITE] = _pipe_state.write.overlap.hEvent;
_events[VD_EVENT_CONTROL] = _control_event;
- _agent_proc_info.hProcess;
_vdi_port->fill_events(&_events[_events_vdi_port_base]);
_chunk_size = _chunk_port = 0;
read_pipe();
@@ -548,22 +547,9 @@ bool VDService::execute()
DWORD wait_ret = WaitForMultipleObjects(actual_events, _events, FALSE,
cont ? 0 : INFINITE);
switch (wait_ret) {
- case WAIT_OBJECT_0 + VD_EVENT_PIPE_READ: {
- DWORD bytes = 0;
- if (_pipe_connected && _pending_read) {
- _pending_read = false;
- if (GetOverlappedResult(_pipe_state.pipe, &_pipe_state.read.overlap,
- &bytes, FALSE) || GetLastError() == ERROR_MORE_DATA) {
- handle_pipe_data(bytes);
- read_pipe();
- } else if (GetLastError() != ERROR_IO_INCOMPLETE) {
- vd_printf("GetOverlappedResult failed %u", GetLastError());
- _pipe_connected = false;
- DisconnectNamedPipe(_pipe_state.pipe);
- }
- }
+ case WAIT_OBJECT_0 + VD_EVENT_PIPE_READ:
+ pipe_read_completion();
break;
- }
case WAIT_OBJECT_0 + VD_EVENT_PIPE_WRITE:
pipe_write_completion();
break;
@@ -884,13 +870,15 @@ bool VDService::launch_agent()
overlap.hEvent = CreateEvent(NULL, FALSE, FALSE, NULL);
DWORD err = (ConnectNamedPipe(_pipe_state.pipe, &overlap) ? 0 : GetLastError());
if (err = ERROR_IO_PENDING) {
- DWORD wait_ret = WaitForSingleObject(overlap.hEvent, 3000);
+ HANDLE wait_handles[2] = {overlap.hEvent, _agent_proc_info.hProcess};
+ DWORD wait_ret = WaitForMultipleObjects(2, wait_handles, FALSE, VD_AGENT_TIMEOUT);
if (wait_ret != WAIT_OBJECT_0) {
- vd_printf("WaitForSingleObject() failed: %u error: %u", wait_ret,
+ _agent_proc_info.hProcess = 0;
+ vd_printf("Failed waiting for vdagent connection: %u error: %u", wait_ret,
wait_ret == WAIT_FAILED ? GetLastError() : 0);
ret = FALSE;
}
- } else if (err != 0 || err != ERROR_PIPE_CONNECTED) {
+ } else if (err != 0 && err != ERROR_PIPE_CONNECTED) {
vd_printf("ConnectNamedPipe() failed: %u", err);
ret = FALSE;
}
@@ -921,14 +909,12 @@ bool VDService::kill_agent()
DisconnectNamedPipe(_pipe_state.pipe);
}
if (GetProcessId(proc_handle)) {
- wait_ret = WaitForSingleObject(proc_handle, 3000);
+ wait_ret = WaitForSingleObject(proc_handle, VD_AGENT_TIMEOUT);
switch (wait_ret) {
case WAIT_OBJECT_0:
if (GetExitCodeProcess(proc_handle, &exit_code)) {
vd_printf("vdagent exit code %u", exit_code);
- } else if (exit_code == STILL_ACTIVE) {
- vd_printf("Failed killing vdagent");
- ret = false;
+ ret = (exit_code != STILL_ACTIVE);
} else {
vd_printf("GetExitCodeProcess() failed: %u", GetLastError());
}
@@ -1005,7 +991,7 @@ void VDService::pipe_write_completion()
_pending_write = true;
if (!WriteFile(ps->pipe, ps->write.data + ps->write.start,
ps->write.end - ps->write.start, NULL, &_pipe_state.write.overlap)) {
- vd_printf("WriteFile() failed: %u", GetLastError());
+ vd_printf("vdagent disconnected (%u)", GetLastError());
_pending_write = false;
_pipe_connected = false;
DisconnectNamedPipe(_pipe_state.pipe);
@@ -1015,6 +1001,33 @@ void VDService::pipe_write_completion()
}
}
+void VDService::pipe_read_completion()
+{
+ DWORD bytes = 0;
+ DWORD err = ERROR_SUCCESS;
+
+ if (!_pipe_connected || !_pending_read) {
+ return;
+ }
+ _pending_read = false;
+ if (!GetOverlappedResult(_pipe_state.pipe, &_pipe_state.read.overlap, &bytes, FALSE)) {
+ err = GetLastError();
+ }
+ switch (err) {
+ case ERROR_SUCCESS:
+ case ERROR_MORE_DATA:
+ handle_pipe_data(bytes);
+ read_pipe();
+ break;
+ case ERROR_IO_INCOMPLETE:
+ break;
+ default:
+ vd_printf("vdagent disconnected (%u)", err);
+ _pipe_connected = false;
+ DisconnectNamedPipe(_pipe_state.pipe);
+ }
+}
+
void VDService::read_pipe()
{
VDPipeState* ps = &_pipe_state;
@@ -1025,11 +1038,10 @@ void VDService::read_pipe()
if (ReadFile(ps->pipe, ps->read.data + ps->read.end, sizeof(ps->read.data) - ps->read.end,
&bytes, &ps->read.overlap) || GetLastError() == ERROR_MORE_DATA) {
_pending_read = false;
- vd_printf("ReadFile without pending %u", bytes);
handle_pipe_data(bytes);
read_pipe();
} else if (GetLastError() != ERROR_IO_PENDING) {
- vd_printf("ReadFile() failed: %u", GetLastError());
+ vd_printf("vdagent disconnected (%u)", GetLastError());
_pending_read = false;
_pipe_connected = false;
DisconnectNamedPipe(_pipe_state.pipe);
More information about the Spice-commits
mailing list