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

Last change on this file since 48 was 48, checked in by sherbold, 14 years ago
  • code clean-up: moved deprecated filter code to a txt-file for potential reuse
  • code clean-up: moved helper functions to separate source code file
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_HSCROLL:
219                        case WM_VSCROLL:
220                        case WM_MENUSELECT:
221                        case WM_USER:
222                                waitResult = WaitForSingleObject(mutex, 1000);
223                                if( waitResult==WAIT_OBJECT_0 ) {
224                                        WriteLogentryWString(msg, nFrom);
225                                        ReleaseMutex(mutex);
226                                }
227#ifdef __TIMING__
228                                msgCounter++;
229                                msgCounterChange = true;
230#endif // __TIMING__
231                                break;
232                        default:
233                                break;
234                }
235        }
236
237#ifdef __TIMING__
238        GetSystemTime( &systemTime );
239        timing += systemTime.wMilliseconds+systemTime.wSecond*1000-startTime;
240        totalMsgCounter++;
241        if( msgCounterChange && msgCounter%100==0 ) {
242#ifdef __USING_MTRACE__
243                char * mtraceBuffer = new char[128];
244                sprintf(mtraceBuffer, "ul timing: %llu \t\t %llu \t\t %llu", timing, msgCounter, totalMsgCounter);
245                MTrace_AddToLevel(traceLevel,mtraceBuffer);
246                delete mtraceBuffer;
247                msgCounterChange = false;
248#endif // __USING_MTRACE__
249        }
250#endif // __TIMING__
251}
252
253
254void WriteLogentryWString(PMSG msg, int nFrom) {
255        wchar_t * messageStr = NULL;
256        wchar_t buffer[128];
257        wchar_t * newWindowText = NULL;
258        wchar_t * windowName = NULL;
259        unsigned int command = 0;
260        int sourceType = -1;
261        HWND source = NULL;
262        HWND parentHandle = NULL;
263        wchar_t * windowClass = NULL;
264        bool isPopup = false;
265        bool isModal = false;
266        bool htMenu = false;
267        HWND menuHandle = NULL;
268        int scrollPos = -1;
269        unsigned int scrollType = 0;
270        HWND scrollBarHandle = NULL;
271        int retVal = 0;
272
273        // debug vars
274       
275        retVal = GetWindowText(msg->hwnd, buffer, 128);
276        if( retVal > 0  && retVal<MAXINT ) {
277                /*
278                 * In one case at the start of MarWin, when a resource with DlgId 1049 is created,
279                 * GetWindowText returns MAXINT. This behaviour is undocumented.
280                 */
281                replaceWithXmlEntitiesWString(buffer, &windowName, retVal+1);
282        }
283        int windowResourceId = GetDlgCtrlID(msg->hwnd);
284        if( windowResourceId<0 ) {
285                windowResourceId = 0;
286        }
287
288        //**************************************
289        // Message specific variables
290        //**************************************
291
292        if( msg->message==WM_COMMAND ) {
293                command = LOWORD(msg->wParam);
294                sourceType = HIWORD(msg->wParam);
295                source = (HWND) msg->lParam;
296        }
297        if( msg->message==WM_SYSCOMMAND ) {
298                command = LOWORD(msg->wParam);
299        }
300
301        if( msg->message==WM_CREATE ) {
302                parentHandle = GetParent(msg->hwnd);
303               
304                retVal = GetClassName(msg->hwnd, buffer, 128);
305                if( retVal > 0  && retVal<MAXINT ) {
306                        replaceWithXmlEntitiesWString(buffer, &windowClass, retVal+1);
307                }
308
309                // check is dialog is modal
310                // this check is not always accurate, but the best that I could come up with
311                isModal = IsWindowEnabled(parentHandle)==false;
312        }
313
314        if( msg->message==WM_SETTEXT ) {
315                wchar_t * newWindowTextBuffer = (wchar_t*)msg->lParam;
316                if( newWindowTextBuffer!=NULL ) {
317                        size_t len = wcslen(newWindowTextBuffer);
318                        replaceWithXmlEntitiesWString(newWindowTextBuffer, &newWindowText, len+1);
319                }
320        }
321
322        if( msg->message==WM_NCLBUTTONDOWN ) {
323                if( msg->wParam==HTMENU ) {
324                        htMenu = true;
325                }
326        }
327       
328        if( msg->message==WM_INITMENU ) {
329                menuHandle = (HWND) msg->wParam;
330        }
331
332        if( msg->message==WM_HSCROLL || msg->message==WM_VSCROLL ) {
333                scrollType = LOWORD(msg->wParam);
334                scrollPos = HIWORD(msg->wParam);
335                scrollBarHandle = (HWND) msg->lParam;
336        }
337
338        /***************************************/
339        // put debugging variables here
340        /***************************************/
341
342
343        /***************************************
344         * Printing part
345         ***************************************/
346       
347        size_t bufsize = 2048;
348        wchar_t * msgBuffer = new wchar_t[bufsize];
349        size_t pos = 0;
350        //pos += swprintf_s(msgBuffer+pos, bufsize-pos,LOGPREFIXWSTRING);
351
352       
353        // print msg information
354        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<msg type=\"%i\">",msg->message);
355        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"WPARAM\" value=\"%i\"/>", msg->wParam);
356        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"LPARAM\" value=\"%i\"/>", msg->lParam);
357
358        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.hwnd\" value=\"%i\"/>", msg->hwnd);
359        if( msg->message==WM_COMMAND ) {
360                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"command\" value=\"%i\"/>",command);
361                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"sourceType\" value=\"%i\"/>",sourceType);
362                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"source\" value=\"%i\"/>",source);
363        }
364        if( msg->message==WM_SYSCOMMAND ) {
365                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"command\" value=\"%i\"/>", command);
366        }
367
368        if( msg->message==WM_LBUTTONUP || msg->message==WM_RBUTTONUP || msg->message==WM_MBUTTONUP ||
369                msg->message==WM_LBUTTONDOWN || msg->message==WM_RBUTTONDOWN || msg->message==WM_MBUTTONDOWN ||
370                msg->message==WM_LBUTTONDBLCLK || msg->message==WM_RBUTTONDBLCLK || msg->message==WM_MBUTTONDBLCLK) {
371                if( msg->time>-1 ) {
372                        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"point.x\" value=\"%i\"/>", msg->pt.x);
373                        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"point.x\" value=\"%i\"/>", msg->pt.y);
374                }
375
376                if(msg->message == WM_LBUTTONUP)
377                {
378                        //check the listBox selection, store it in "scrollPos"
379                        //no selection = -1
380                        //this is only working for listBoxes with style 'selection = single'
381                        retVal = GetClassName(msg->hwnd, buffer, 128);
382                        if( retVal >= -1  && retVal < MAXINT && !lstrcmpi(buffer, L"ListBox") )
383                        {
384                                scrollPos = (int)SendMessage(msg->hwnd, LB_GETCURSEL, 0, 0);
385                                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"scrollPos\" value=\"%i\"/>", scrollPos);
386                        }
387
388
389                        //check the TabControl selection, store it in "scrollPos"
390                        //no selection = -1
391                        retVal = GetClassName(msg->hwnd, buffer, 128);
392                        if( retVal >= -1  && retVal < MAXINT && !lstrcmpi(buffer, L"SysTabControl32") )
393                        {
394                                scrollPos = (int)SendMessage(msg->hwnd, (UINT)4875, 0, 0);
395                                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"scrollPos\" value=\"%i\"/>", scrollPos);
396                        }
397                }
398        }
399        if( msg->message==WM_MOUSEACTIVATE ) {
400                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"toplevelwindow.hwnd\" value=\"%i\"/>", (HWND) msg->wParam);
401        }
402        if( msg->message==WM_KEYUP || msg->message==WM_KEYDOWN || msg->message==WM_SYSKEYUP || msg->message==WM_SYSKEYDOWN ) {
403                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"key\" value=\"%i\"/>", LOWORD(msg->wParam));
404        }
405        if( msg->message==WM_SETTEXT ) {
406                if( newWindowText!=NULL ) {
407                        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.newText\" value=\"%s\"/>", newWindowText);
408                }
409        }
410       
411        if( msg->message==WM_NCLBUTTONDOWN && htMenu ) {
412                pos += swprintf_s(msgBuffer+pos, bufsize-pos,L"<param name=\"isMenu\" value=\"true\"/>");
413        }
414
415        if( msg->message==WM_INITMENU ) {
416                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"menu.hwnd\" value=\"%i\"/>", menuHandle);
417        }
418
419        if( msg->message==WM_CREATE ) {
420                // print window information
421                if( windowName!=NULL ) {
422                        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.name\" value=\"%s\"/>", windowName);
423                }
424                if( windowResourceId>0 ) {
425                        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.resourceId\" value=\"%i\"/>", windowResourceId);
426                }
427                if( msg->message==WM_CREATE ) {
428                        if( parentHandle!=NULL ) {
429                                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.parent.hwnd\" value=\"%i\"/>", parentHandle);
430                        }
431                        if( windowClass!=NULL ) {
432                                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.class\" value=\"%s\"/>", windowClass);
433                        }
434                        if( isModal ) {
435                                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"window.ismodal\" value=\"true\"/>");
436                        }
437
438                }
439        }
440        if( msg->message==WM_HSCROLL || msg->message==WM_VSCROLL ) {
441                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"scrollType\" value=\"%i\"/>", scrollType);
442                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"scrollPos\" value=\"%i\"/>", scrollPos);
443                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"scrollBarHandle\" value=\"%i\"/>", scrollBarHandle);
444        }
445
446        if( msg->time!=-1 ) {
447                pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"time\" value=\"%i\"/>", msg->time);
448        }
449       
450        /***************************************/
451        // put debugging and experimental output stuff here
452        /***************************************/
453
454#ifdef __INCLUDEHOOKINFO__
455        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"<param name=\"hook\" value=\"%i\"/>", nFrom);
456#endif
457       
458
459        pos += swprintf_s(msgBuffer+pos,bufsize-pos,L"</msg>", msg->hwnd);
460#ifdef __USING_MTRACE__
461#ifdef __ENCODE_BASE64__
462        size_t arraySize = (pos+1)*2;
463        size_t encodingSize = arraySize*2;
464        char * base64Buffer = new char[encodingSize];
465
466        base64::encoder enc;
467        retVal = enc.encode((char*)msgBuffer, arraySize, base64Buffer);
468        base64Buffer[retVal] = '\0';
469
470        char * mtraceBuffer = new char[retVal+30];
471        sprintf_s(mtraceBuffer,retVal+29,"%s%s", LOGPREFIX, base64Buffer);
472        delete base64Buffer;
473#else
474        char * mtraceBuffer = new char[pos+1];
475        size_t numConverted;
476        wcstombs_s(&numConverted,mtraceBuffer, pos+1, msgBuffer, pos);
477#endif // __ENCODE_BASE64__
478        MTrace_AddToLevel(traceLevel,mtraceBuffer);
479        delete mtraceBuffer;
480#endif // __USING_MTRACE__
481#ifdef __USING_COSTUMLOG__
482        SYSTEMTIME currentTime;
483        GetSystemTime(&currentTime);
484        logfile << currentTime.wDay << "." << currentTime.wMonth << "." << currentTime.wYear << " ";
485        logfile << currentTime.wHour << ":" << currentTime.wMinute << ":" << currentTime.wSecond << ":";
486        logfile << currentTime.wMilliseconds << "\t";
487        logfile << buffer << std::endl;
488#endif
489        delete messageStr;
490        delete newWindowText;
491        delete windowName;
492        delete windowClass;
493        delete msgBuffer;
494}
Note: See TracBrowser for help on using the repository browser.