source: trunk/MFCtooling/userlog/userlog.cpp @ 86

Last change on this file since 86 was 64, checked in by sherbold, 13 years ago
  • added logging of coordinates for non-client mouse clicks (e.g., WM_NCLBUTTONDOWN)
File size: 16.1 KB
Line 
1#include "stdafx.h"
2#include "userlog.h"
3#include "windowsx.h"
4
5#include <map>
6#include <cstdio>
7
8#include "helpers.h"
9
10#ifdef __USING_MTRACE__
11#define OS_WIN32
12#include "msl/merror/inc/trace.h"
13
14#ifdef __ENCODE_BASE64__
15#include  "encode.h"
16#endif
17
18const static int traceLevel = 3;
19static int level;
20#endif
21
22#ifdef __USING_COSTUMLOG__
23static std::ofstream logfile;
24#endif
25
26#ifdef __TIMING__
27static unsigned long long timing = 0;
28static unsigned long long msgCounter = 0;
29static unsigned long long totalMsgCounter = 0;
30static bool msgCounterChange = false;
31#endif
32
33static MSG lastmsg;
34
35static bool keysPressed[256];
36
37inline bool keyAlreadyPressed(const MSG & msg) {
38        return (msg.message==WM_KEYDOWN || msg.message==WM_SYSKEYDOWN) && keysPressed[msg.wParam];
39}
40
41inline bool keyNotPressed(const MSG & msg) {
42        return (msg.message==WM_KEYUP || msg.message==WM_SYSKEYUP) && !keysPressed[msg.wParam];
43}
44
45
46HANDLE mutex;
47
48
49
50USERLOG_API void __cdecl InitUsagelog() {
51
52        mutex = CreateMutex(NULL, FALSE, TEXT("USAGELOGMUTEX"));
53        if( mutex == NULL ) {
54                MessageBox(0, L"MutexFailure", L"MutexFailure", 0);
55        }
56        for(int i=0; i<256; i++) {
57                keysPressed[i] = false;
58        }
59
60#ifdef __USING_COSTUMLOG__
61        InitLogfile();
62#endif
63        InitHookdata();
64        InitHooks();
65#ifdef __USING_MTRACE__
66        MTrace_AddToLevel(traceLevel,"%s<session>", LOGPREFIX);
67#endif
68#ifdef __USING_COSTUMLOG__
69        logfile << LOGPREFIX << "<session>" << std::endl;
70#endif
71}
72
73USERLOG_API void __cdecl ReleaseUsagelog() {
74        ReleaseHooks();
75#ifdef __USING_MTRACE__
76#ifdef __TIMING__
77        char * mtraceBuffer = new char[128];
78        sprintf(mtraceBuffer, "ul timing: %llu \t\t %llu \t\t %llu", timing, msgCounter, totalMsgCounter);
79        MTrace_AddToLevel(traceLevel,mtraceBuffer);
80        delete mtraceBuffer;
81        msgCounterChange = false;
82#endif
83        MTrace_AddToLevel(traceLevel,"%s</session>", LOGPREFIX);
84#endif
85#ifdef __USING_COSTUMLOG__
86        logfile << LOGPREFIX << "</session>" << std::endl;
87        CloseLogfile();
88#endif
89}
90
91#ifdef __USING_COSTUMLOG__
92void InitLogfile() {
93        logfile.open(LOGFILE, std::ios_base::app);
94        if( logfile.fail() ) {
95                MessageBox(0, L"Logfile could not be opend", L"Error", MB_OK);
96        }
97}
98#endif
99
100#ifdef __USING_COSTUMLOG__
101void CloseLogfile() {
102        logfile.close();
103}
104#endif
105
106void InitHookdata() {
107        myhookdata[CALLWNDHOOKID].nType = WH_CALLWNDPROC;
108        myhookdata[CALLWNDHOOKID].hkproc = CallWndProc;
109        myhookdata[GETMSGHOOKID].nType = WH_GETMESSAGE;
110        myhookdata[GETMSGHOOKID].hkproc = GetMsgProc;
111}
112
113void InitHooks() {
114        for( int i=0 ; i<NUMHOOKS ; i++ ) {
115                myhookdata[i].hookhandle = SetWindowsHookEx(myhookdata[i].nType, myhookdata[i].hkproc, (HINSTANCE) NULL, GetCurrentThreadId());
116                if( myhookdata[i].hookhandle!=NULL ) {
117                        myhookdata[i].active = true;
118                } else {
119                        myhookdata[i].active = false;
120                }
121        }
122}
123
124void ReleaseHooks() {
125        int counter = 0;
126        for( int i=0 ; i<NUMHOOKS ; i++ ) {
127                if( UnhookWindowsHookEx(myhookdata[i].hookhandle) ) counter++;
128        }
129}
130
131
132LRESULT CALLBACK CallWndProc(int nCode, WPARAM wParam, LPARAM lParam) {
133       
134        PCWPSTRUCT cwpMsg = (PCWPSTRUCT) lParam;
135        // Create a MSG struct from the cwpMsg struct
136        // The missing parameters are filled with dummy values
137        MSG msg;
138        msg.hwnd = cwpMsg->hwnd;
139        msg.message = cwpMsg->message;
140        msg.lParam = cwpMsg->lParam;
141        msg.wParam = cwpMsg->wParam;
142        msg.pt.x = -1;
143        msg.pt.y = -1;
144        msg.time = -1;
145        HookProc(CALLWNDHOOKID, nCode, &msg);
146
147        return CallNextHookEx(myhookdata[CALLWNDHOOKID].hookhandle, nCode, wParam, lParam);
148}
149
150LRESULT CALLBACK GetMsgProc(int nCode, WPARAM wParam, LPARAM lParam) {
151        PMSG msg = (PMSG) lParam;
152        HookProc(GETMSGHOOKID,nCode, msg);
153
154        return CallNextHookEx(myhookdata[GETMSGHOOKID].hookhandle, nCode, wParam, lParam);
155}
156
157void HookProc(int nFrom, int nCode, PMSG msg) {
158#ifdef __TIMING__
159        SYSTEMTIME systemTime;
160        GetSystemTime( &systemTime );
161        int startTime = systemTime.wMilliseconds+systemTime.wSecond*1000;
162#endif
163
164        DWORD waitResult;
165        // simple heuristic to eliminate duplicate messages
166        if( !( MessageEquals(*msg, lastmsg) || keyAlreadyPressed(*msg) || keyNotPressed(*msg) ) ) {
167                lastmsg = *msg;
168                if( msg->message==WM_KEYDOWN || msg->message==WM_SYSKEYDOWN ) {
169                        keysPressed[msg->wParam] = true;
170                }
171                if( msg->message==WM_KEYUP || msg->message==WM_SYSKEYUP ) {
172                        keysPressed[msg->wParam] = false;
173                }
174
175                // message filter:
176                // all messages that are defined in this switch statement will be part of the log
177                switch(msg->message) {
178                        // messages for monitoring GUI state
179                        case WM_CREATE:
180                        case WM_DESTROY:
181                        case WM_SETTEXT:
182
183                        // mouse messages
184                        case WM_LBUTTONDOWN:
185                        case WM_LBUTTONUP:
186                        case WM_LBUTTONDBLCLK:
187                        case WM_RBUTTONDOWN:
188                        case WM_RBUTTONUP:
189                        case WM_RBUTTONDBLCLK:
190                        case WM_MBUTTONDOWN:
191                        case WM_MBUTTONUP:
192                        case WM_MBUTTONDBLCLK:
193                        case WM_XBUTTONDOWN:
194                        case WM_XBUTTONUP:
195                        case WM_XBUTTONDBLCLK:
196                        case WM_NCLBUTTONDOWN:
197                        case WM_NCLBUTTONUP:
198                        case WM_NCLBUTTONDBLCLK:
199                        case WM_NCRBUTTONDOWN:
200                        case WM_NCRBUTTONUP:
201                        case WM_NCRBUTTONDBLCLK:
202                        case WM_NCMBUTTONDOWN:
203                        case WM_NCMBUTTONUP:
204                        case WM_NCMBUTTONDBLCLK:
205                        case WM_NCXBUTTONDOWN:
206                        case WM_NCXBUTTONUP:
207                        case WM_NCXBUTTONDBLCLK:
208
209                        // keyboard messages
210                        case WM_KEYDOWN:
211                        case WM_KEYUP:
212                        case WM_SYSKEYDOWN:
213                        case WM_SYSKEYUP:
214
215                        // internal messages usefull for replay/matching of events
216                        case WM_KILLFOCUS:
217                        case WM_SETFOCUS:
218                        case WM_COMMAND:
219                        case WM_SYSCOMMAND:
220                        case WM_HSCROLL:
221                        case WM_VSCROLL:
222                        case WM_MENUSELECT:
223                        case WM_USER:
224                                waitResult = WaitForSingleObject(mutex, 1000);
225                                if( waitResult==WAIT_OBJECT_0 ) {
226                                        WriteLogentryWString(msg, nFrom);
227                                        ReleaseMutex(mutex);
228                                }
229#ifdef __TIMING__
230                                msgCounter++;
231                                msgCounterChange = true;
232#endif // __TIMING__
233                                break;
234                        default:
235                                break;
236                }
237        }
238
239#ifdef __TIMING__
240        GetSystemTime( &systemTime );
241        timing += systemTime.wMilliseconds+systemTime.wSecond*1000-startTime;
242        totalMsgCounter++;
243        if( msgCounterChange && msgCounter%100==0 ) {
244#ifdef __USING_MTRACE__
245                char * mtraceBuffer = new char[128];
246                sprintf(mtraceBuffer, "ul timing: %llu \t\t %llu \t\t %llu", timing, msgCounter, totalMsgCounter);
247                MTrace_AddToLevel(traceLevel,mtraceBuffer);
248                delete mtraceBuffer;
249                msgCounterChange = false;
250#endif // __USING_MTRACE__
251        }
252#endif // __TIMING__
253}
254
255
256void WriteLogentryWString(PMSG msg, int nFrom) {
257        wchar_t * messageStr = NULL;
258        wchar_t buffer[128];
259        wchar_t * newWindowText = NULL;
260        wchar_t * windowName = NULL;
261        unsigned int command = 0;
262        int sourceType = -1;
263        HWND source = NULL;
264        HWND parentHandle = NULL;
265        wchar_t * windowClass = NULL;
266        bool isPopup = false;
267        bool isModal = false;
268        bool htMenu = false;
269        HWND menuHandle = NULL;
270        int scrollPos = -1;
271        unsigned int scrollType = 0;
272        HWND scrollBarHandle = NULL;
273        int retVal = 0;
274        int pointx = -1;
275        int pointy = -1;
276
277        // debug vars
278       
279        retVal = GetWindowText(msg->hwnd, buffer, 128);
280        if( retVal > 0  && retVal<MAXINT ) {
281                /*
282                 * In one case at the start of MarWin, when a resource with DlgId 1049 is created,
283                 * GetWindowText returns MAXINT. This behaviour is undocumented.
284                 */
285                replaceWithXmlEntitiesWString(buffer, &windowName, retVal+1);
286        }
287        int windowResourceId = GetDlgCtrlID(msg->hwnd);
288        if( windowResourceId<0 ) {
289                windowResourceId = 0;
290        }
291
292        //**************************************
293        // Message specific variables
294        //**************************************
295
296        if( msg->message==WM_COMMAND ) {
297                command = LOWORD(msg->wParam);
298                sourceType = HIWORD(msg->wParam);
299                source = (HWND) msg->lParam;
300        }
301        if( msg->message==WM_SYSCOMMAND ) {
302                command = LOWORD(msg->wParam);
303        }
304
305        if( msg->message==WM_CREATE ) {
306                parentHandle = GetParent(msg->hwnd);
307               
308                retVal = GetClassName(msg->hwnd, buffer, 128);
309                if( retVal > 0  && retVal<MAXINT ) {
310                        replaceWithXmlEntitiesWString(buffer, &windowClass, retVal+1);
311                }
312
313                // check is dialog is modal
314                // this check is not always accurate, but the best that I could come up with
315                isModal = IsWindowEnabled(parentHandle)==false;
316        }
317
318        if( msg->message==WM_SETTEXT ) {
319                wchar_t * newWindowTextBuffer = (wchar_t*)msg->lParam;
320                if( newWindowTextBuffer!=NULL ) {
321                        size_t len = wcslen(newWindowTextBuffer);
322                        replaceWithXmlEntitiesWString(newWindowTextBuffer, &newWindowText, len+1);
323                }
324        }
325
326        if( msg->message==WM_LBUTTONUP || msg->message==WM_RBUTTONUP || msg->message==WM_MBUTTONUP ||
327                msg->message==WM_LBUTTONDOWN || msg->message==WM_RBUTTONDOWN || msg->message==WM_MBUTTONDOWN ||
328                msg->message==WM_LBUTTONDBLCLK || msg->message==WM_RBUTTONDBLCLK || msg->message==WM_MBUTTONDBLCLK ||
329                msg->message==WM_NCLBUTTONUP || msg->message==WM_NCRBUTTONUP || msg->message==WM_NCMBUTTONUP ||
330                msg->message==WM_NCLBUTTONDOWN || msg->message==WM_NCRBUTTONDOWN || msg->message==WM_NCMBUTTONDOWN ||
331                msg->message==WM_NCLBUTTONDBLCLK || msg->message==WM_NCRBUTTONDBLCLK || msg->message==WM_NCMBUTTONDBLCLK) {
332               
333                RECT r;
334                DWORD dCursorPos = GetMessagePos();
335                GetWindowRect(msg->hwnd, &r);
336                //dont log absolut coordinates but relativ ones so you can use them in rule "LeftClickRelativ"
337                pointx = GET_X_LPARAM(dCursorPos)-r.left;
338                pointy = GET_Y_LPARAM(dCursorPos)-r.top;
339        }
340
341        if( msg->message==WM_NCLBUTTONDOWN ) {
342                if( msg->wParam==HTMENU ) {
343                        htMenu = true;
344                }
345        }
346       
347        if( msg->message==WM_INITMENU ) {
348                menuHandle = (HWND) msg->wParam;
349        }
350
351        if( msg->message==WM_HSCROLL || msg->message==WM_VSCROLL ) {
352                scrollType = LOWORD(msg->wParam);
353                scrollPos = HIWORD(msg->wParam);
354                scrollBarHandle = (HWND) msg->lParam;
355        }
356
357        /***************************************/
358        // put debugging variables here
359        /***************************************/
360
361
362        /***************************************
363         * Printing part
364         ***************************************/
365       
366        size_t bufsize = 2048;
367        wchar_t * msgBuffer = new wchar_t[bufsize];
368        size_t pos = 0;
369        //pos += swprintf_s(msgBuffer+pos, bufsize-pos,LOGPREFIXWSTRING);
370
371       
372        // print msg information
373        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<msg type=\"%i\">",msg->message);
374        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"WPARAM\" value=\"%i\"/>", msg->wParam);
375        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"LPARAM\" value=\"%i\"/>", msg->lParam);
376
377        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.hwnd\" value=\"%i\"/>", msg->hwnd);
378        if( msg->message==WM_COMMAND ) {
379                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"command\" value=\"%i\"/>",command);
380                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"sourceType\" value=\"%i\"/>",sourceType);
381                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"source\" value=\"%i\"/>",source);
382        }
383        if( msg->message==WM_SYSCOMMAND ) {
384                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"command\" value=\"%i\"/>", command);
385        }
386
387        if( msg->message==WM_LBUTTONUP || msg->message==WM_RBUTTONUP || msg->message==WM_MBUTTONUP ||
388                msg->message==WM_LBUTTONDOWN || msg->message==WM_RBUTTONDOWN || msg->message==WM_MBUTTONDOWN ||
389                msg->message==WM_LBUTTONDBLCLK || msg->message==WM_RBUTTONDBLCLK || msg->message==WM_MBUTTONDBLCLK ||
390                msg->message==WM_NCLBUTTONUP || msg->message==WM_NCRBUTTONUP || msg->message==WM_NCMBUTTONUP ||
391                msg->message==WM_NCLBUTTONDOWN || msg->message==WM_NCRBUTTONDOWN || msg->message==WM_NCMBUTTONDOWN ||
392                msg->message==WM_NCLBUTTONDBLCLK || msg->message==WM_NCRBUTTONDBLCLK || msg->message==WM_NCMBUTTONDBLCLK) {
393               
394               
395                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"point.x\" value=\"%i\"/>", pointx);
396                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"point.y\" value=\"%i\"/>", pointy);
397                       
398                if(msg->message == WM_LBUTTONUP)
399                {
400                        //check the listBox selection, store it in "scrollPos"
401                        //no selection = -1
402                        //this is only working for listBoxes with style 'selection = single'
403                        retVal = GetClassName(msg->hwnd, buffer, 128);
404                        if( retVal >= -1  && retVal < MAXINT && !lstrcmpi(buffer, L"ListBox") )
405                        {
406                                scrollPos = (int)SendMessage(msg->hwnd, LB_GETCURSEL, 0, 0);
407                                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"scrollPos\" value=\"%i\"/>", scrollPos);
408                        }
409
410                        //check the TabControl selection, store it in "scrollPos"
411                        //no selection = -1
412                        retVal = GetClassName(msg->hwnd, buffer, 128);
413                        if( retVal >= -1  && retVal < MAXINT && !lstrcmpi(buffer, L"SysTabControl32") )
414                        {
415                                scrollPos = (int)SendMessage(msg->hwnd, (UINT)4875, 0, 0);
416                                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"scrollPos\" value=\"%i\"/>", scrollPos);
417                        }
418                }
419        }
420        if( msg->message==WM_MOUSEACTIVATE ) {
421                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"toplevelwindow.hwnd\" value=\"%i\"/>", (HWND) msg->wParam);
422        }
423        if( msg->message==WM_KEYUP || msg->message==WM_KEYDOWN || msg->message==WM_SYSKEYUP || msg->message==WM_SYSKEYDOWN ) {
424                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"key\" value=\"%i\"/>", LOWORD(msg->wParam));
425        }
426        if( msg->message==WM_SETTEXT ) {
427                if( newWindowText!=NULL ) {
428                        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.newText\" value=\"%s\"/>", newWindowText);
429                }
430        }
431       
432        if( msg->message==WM_NCLBUTTONDOWN && htMenu ) {
433                pos += swprintf_s(msgBuffer+pos, bufsize-pos,L"<param name=\"isMenu\" value=\"true\"/>");
434        }
435
436        if( msg->message==WM_INITMENU ) {
437                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"menu.hwnd\" value=\"%i\"/>", menuHandle);
438        }
439
440        if( msg->message==WM_CREATE ) {
441                // print window information
442                if( windowName!=NULL ) {
443                        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.name\" value=\"%s\"/>", windowName);
444                }
445                if( windowResourceId>0 ) {
446                        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.resourceId\" value=\"%i\"/>", windowResourceId);
447                }
448                if( msg->message==WM_CREATE ) {
449                        if( parentHandle!=NULL ) {
450                                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.parent.hwnd\" value=\"%i\"/>", parentHandle);
451                        }
452                        if( windowClass!=NULL ) {
453                                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.class\" value=\"%s\"/>", windowClass);
454                        }
455                        if( isModal ) {
456                                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.ismodal\" value=\"true\"/>");
457                        }
458
459                }
460        }
461        if( msg->message==WM_HSCROLL || msg->message==WM_VSCROLL ) {
462                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"scrollType\" value=\"%i\"/>", scrollType);
463                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"scrollPos\" value=\"%i\"/>", scrollPos);
464                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"scrollBarHandle\" value=\"%i\"/>", scrollBarHandle);
465        }
466
467        if( msg->time!=-1 ) {
468                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"time\" value=\"%i\"/>", msg->time);
469        }
470       
471        /***************************************/
472        // put debugging and experimental output stuff here
473        /***************************************/
474
475#ifdef __INCLUDEHOOKINFO__
476        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"hook\" value=\"%i\"/>", nFrom);
477#endif
478       
479
480        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"</msg>", msg->hwnd);
481#ifdef __USING_MTRACE__
482#ifdef __ENCODE_BASE64__
483        size_t arraySize = (pos+1)*2;
484        size_t encodingSize = arraySize*2;
485        char * base64Buffer = new char[encodingSize];
486
487        base64::encoder enc;
488        retVal = enc.encode((char*)msgBuffer, arraySize, base64Buffer);
489        base64Buffer[retVal] = '\0';
490
491        char * mtraceBuffer = new char[retVal+30];
492        sprintf_s(mtraceBuffer,retVal+29,"%s%s", LOGPREFIX, base64Buffer);
493        delete base64Buffer;
494#else
495        char * mtraceBuffer = new char[pos+1];
496        size_t numConverted;
497        wcstombs_s(&numConverted,mtraceBuffer, pos+1, msgBuffer, pos);
498#endif // __ENCODE_BASE64__
499        MTrace_AddToLevel(traceLevel,mtraceBuffer);
500        delete mtraceBuffer;
501#endif // __USING_MTRACE__
502#ifdef __USING_COSTUMLOG__
503        SYSTEMTIME currentTime;
504        GetSystemTime(&currentTime);
505        logfile << currentTime.wDay << "." << currentTime.wMonth << "." << currentTime.wYear << " ";
506        logfile << currentTime.wHour << ":" << currentTime.wMinute << ":" << currentTime.wSecond << ":";
507        logfile << currentTime.wMilliseconds << "\t";
508        logfile << buffer << std::endl;
509#endif
510        delete messageStr;
511        delete newWindowText;
512        delete windowName;
513        delete windowClass;
514        delete msgBuffer;
515}
Note: See TracBrowser for help on using the repository browser.