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

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