Windows Mobile: Some Logging Tools

If you ever had a Windows mobile device that behaved strange, you might need some logging to find the cause.

Here is a collection of logging tools I wrote:

BatteryLog

BatteryLog logs the status of battery and power management changes (i.e., Suspend/Resume, etc.)

Instead of just querying the PowerStatusEx, the code uses a thread to watch for PowerNotifications.

...
    // Request power notifications 
    HANDLE hPowerNotifications = RequestPowerNotifications(hPowerMsgQ,
                                                           PBT_TRANSITION | 
                                                           PBT_RESUME | 
                                                           PBT_POWERINFOCHANGE);
    if (NULL == hPowerNotifications) 
    {
        RETAILMSG(1, (L"RequestPowerNotifications failed: %x\n", GetLastError()));
        goto Error;
    }

    HANDLE rgHandles[2] = {0};
    rgHandles[0] = hPowerMsgQ;
    rgHandles[1] = g_hEventShutDown;

    // Wait for a power notification or for the app to exit
    while(WaitForMultipleObjects(2, rgHandles, FALSE, INFINITE) == WAIT_OBJECT_0)
    {
        DWORD cbRead;
        DWORD dwFlags;
        POWER_BROADCAST *ppb = (POWER_BROADCAST*) new BYTE[cbPowerMsgSize];
        TCHAR* szPPB = new TCHAR[MAX_PATH];  
        memset(szPPB, 0, MAX_PATH * 2);
        TCHAR* szPBtype=new TCHAR[MAX_PATH];
        memset(szPBtype, 0, MAX_PATH * 2);
        TCHAR szOut[MAX_PATH];
        // loop through in case there is more than 1 msg 
        while(ReadMsgQueue(hPowerMsgQ, ppb, cbPowerMsgSize, &cbRead, 
                           0, &dwFlags))
        {
            wsprintf(szPPB, L"");
            wsprintf(szPBtype, L"");
            switch (ppb->Message)
            {
                case PBT_POWERSTATUSCHANGE:
                    RETAILMSG(1,(L"Power Notification Message: PBT_POWERSTATUSCHANGE\n"));
                    wsprintf(szPBtype, L"change: ");
                    //Add2Log(L"Power Notification Message: PBT_POWERSTATUSCHANGE\n",TRUE);
                    break;
                case PBT_SUSPENDKEYPRESSED:
                    RETAILMSG(1,(L"Power Notification Message: PBT_SUSPENDKEYPRESSED\n"));
                    wsprintf(szPBtype, L"keypress: ");
                    //Add2Log(L"Power Notification Message: PBT_SUSPENDKEYPRESSED\n",TRUE);
                    break;
...

So the code does not miss changes. But remember, a suspend is signaled at the next resume!

BTmon

BTmon logs BT activity of your device. Handles Device connect/disconnect and other events and logs them to a file.

Fortunately Microsoft provides a message queue for BT events too. So the code uses a similar approach as batteryLog:

void startMsgQueue(HWND hWnd){
    DEBUGMSG(1, (L"Entering msgQueue with hwnd=%i\n", hWnd));

    MSGQUEUEOPTIONS mqOptions;
    memset (&mqOptions, 0, sizeof(mqOptions));

    mqOptions.dwFlags = 0;
    mqOptions.dwSize = sizeof(mqOptions);
    mqOptions.dwMaxMessages = 10;
    mqOptions.cbMaxMessage = sizeof(BTEVENT);
    mqOptions.bReadAccess = TRUE;

    hMsgQ = CreateMsgQueue(NULL, &mqOptions);
    if (! hMsgQ) {
        nclog(L"Error creating message queue.\n");
        goto exit;
    }
    hBTNotif = RequestBluetoothNotifications(
        BTE_CLASS_CONNECTIONS    |
            BTE_CONNECTION            |
            BTE_DISCONNECTION        |
            BTE_ROLE_SWITCH            |
            BTE_MODE_CHANGE            |
            BTE_PAGE_TIMEOUT        |
            BTE_CONNECTION_AUTH_FAILURE    |
        BTE_CLASS_PAIRING    |
            BTE_KEY_NOTIFY    |
            BTE_KEY_REVOKED    |
        BTE_CLASS_DEVICE    |
            BTE_LOCAL_NAME    |
            BTE_COD            |
        BTE_CLASS_STACK        |
            BTE_STACK_UP    |
            BTE_STACK_DOWN    
        , hMsgQ);

    bStop=FALSE;
    CreateThread(NULL, 0, msgThread, hWnd, 0, &threadID);

exit:
    ;
}
...
DWORD msgThread(LPVOID lpParam){
    HWND hWnd = (HWND)lpParam;
    hwndMsg=hWnd;

    DEBUGMSG(1,(L"Waiting for Bluetooth notifications with hwnd=%i...\n", hWnd));
    nclog(L"%s: Waiting for Bluetooth notifications...\n", logDateTime());
    
    TCHAR szMsg[MAX_PATH];
    wsprintf(szMsg, L"\r\n%s: Waiting for Bluetooth notifications...", logDateTime());
    printMsg(szMsg, hWnd);

    BTEVENT btEvent;
    DWORD dwBytesRead;
    DWORD dwFlags;
    BOOL fRet;

    while (FALSE == bStop) {
        DWORD dwWait = WaitForSingleObject (hMsgQ, 5000);//wait up to 5 seconds INFINITE);
        switch (dwWait){
            case WAIT_OBJECT_0:
                // We have got a Bluetooth event!
                dwFlags = 0;
                dwBytesRead = 0;

                fRet = ReadMsgQueue (hMsgQ, &btEvent, 
                sizeof(BTEVENT), &dwBytesRead, 10, &dwFlags);
                if (! fRet) {
                    DEBUGMSG(1,(L"Error - Failed to read message from queue!\n"));
                    //bStop=TRUE;
                } 
                else {
                    dumpBTevent(btEvent, hWnd);
                }
                break;
            case WAIT_TIMEOUT:
...

The ‘problem’ with that is that the events contain different data and every type has to be handled very differently. Here is just a small example:

...
void dumpBTevent(BTEVENT btEvent, HWND hwnd){
    BT_CONNECT_EVENT* cntEvt = NULL;
    BT_DISCONNECT_EVENT* discntEvt=NULL;
    BT_ROLE_SWITCH_EVENT* rolSwitchEvt=NULL;
    BT_MODE_CHANGE_EVENT* btModeChgEvt=NULL;
    BT_LINK_KEY_EVENT* btLnkKeyEvt=NULL;

    TCHAR btAddress[18];
    TCHAR hConn[12];
    TCHAR encMode[5];
    TCHAR linkType[5];
    TCHAR szTemp[MAX_PATH];
    TCHAR szMsg[MAX_PATH];

    wsprintf(szMsg, L"\r\n");

    switch (btEvent.dwEventId){
        case BTE_KEY_NOTIFY:
            wsprintf(szMsg, L"\r\n%s: BTE_KEY_NOTIFY:", logDateTime());
            break;
        case BTE_KEY_REVOKED:
            btLnkKeyEvt = (BT_LINK_KEY_EVENT*)btEvent.baEventData;
            //XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
            wsprintf(btAddress, L"%s", btAddr2Mac( btLnkKeyEvt->bta, btAddress));
            wsprintf(szMsg, L"\r\n%s: BTE_KEY_REVOKED: mac=%s", logDateTime(), btAddress);
            break;
        case BTE_LOCAL_NAME:
            wsprintf(szMsg, L"\r\n%s: BTE_LOCAL_NAME:", logDateTime());
            break;
...

connMgrLog

connMgrLog log connection manager events and connection state changes.

This logging tool currently does not log to file. The code also uses a notification event supported by the Microsoft ConnMgr API. The background thread receiving the notification message will post another message to update the main window with the current event data:

connStats connectionStates[]={
    {L"CONNMGR_STATUS_UNKNOWN", 0x00},
    {L"CONNMGR_STATUS_CONNECTED", 0x10 },
    {L"CONNMGR_STATUS_SUSPENDED", 0x11 },
    {L"CONNMGR_STATUS_DISCONNECTED", 0x20 },
    {L"CONNMGR_STATUS_CONNECTIONFAILED", 0x21 },
    {L"CONNMGR_STATUS_CONNECTIONCANCELED", 0x22 },
    {L"CONNMGR_STATUS_CONNECTIONDISABLED", 0x23 },
    {L"CONNMGR_STATUS_NOPATHTODESTINATION", 0x24 },
    {L"CONNMGR_STATUS_WAITINGFORPATH", 0x25 },
    {L"CONNMGR_STATUS_WAITINGFORPHONE", 0x26 },
    {L"CONNMGR_STATUS_PHONEOFF", 0x27 },
    {L"CONNMGR_STATUS_EXCLUSIVECONFLICT", 0x28 },
    {L"CONNMGR_STATUS_NORESOURCES", 0x29 },
    {L"CONNMGR_STATUS_CONNECTIONLINKFAILED", 0x2A },
    {L"CONNMGR_STATUS_AUTHENTICATIONFAILED", 0x2B },
    {L"CONNMGR_STATUS_WAITINGCONNECTION", 0x40 },
    {L"CONNMGR_STATUS_WAITINGFORRESOURCE", 0x41 },
    {L"CONNMGR_STATUS_WAITINGFORNETWORK", 0x42 },
    {L"CONNMGR_STATUS_WAITINGDISCONNECTION", 0x80 },
    {L"CONNMGR_STATUS_WAITINGCONNECTIONABORT", 0x81 },
    {NULL, -1},
};

UINT WM_CM_STATUS_CHANGE = WM_USER+1234;
...
void startConnMgrWatch(HWND hWnd){
    HRESULT hr;
    hEdit=hWnd;
    if(WM_CM_STATUS_CHANGE==WM_USER+1234){    // do only once, if 1234 then not registered
        WM_CM_STATUS_CHANGE = RegisterWindowMessage( CONNMGR_STATUS_CHANGE_NOTIFICATION_MSG );
        //DEBUGMSG(1, (L"RegisterWindowMessage =0x%x.\r\n", WM_CM_STATUS_CHANGE));
        logMsg(L"RegisterWindowMessage =0x%x.\r\n", WM_CM_STATUS_CHANGE);
    }
    // after you registered for the CONNMGR_STATUS_CHANGE_NOTIFICATION_MSG 
    // and got a constant you can watch for changes
    hr = ConnMgrRegisterForStatusChangeNotification(TRUE, hWnd);
    DEBUGMSG(1, (L"ConnMgrRegisterForStatusChangeNotification =0x%x.\r\n", hr));
    return;
}
...
void dump_details_params(CONNMGR_CONNECTION_DETAILED_STATUS *p){
    //DEBUGMSG(1, (L"\r\n############################################\r\n"));
    logMsg(L"\r\n############################################\r\n");
    //check which flags are valid and dump them
    if(p->dwParams & CONNMGRDETAILEDSTATUS_PARAM_TYPE)
    {   //The dwType member of CONNMGR_CONNECTION_DETAILED_STATUS is valid
        //DEBUGMSG(1,(L"\tConnType= '%s'\r\n", szConnType[p->dwType]));
        logMsg(L"\tConnType= '%s'\r\n", szConnType[p->dwType]);
    }
    if(p->dwParams & CONNMGRDETAILEDSTATUS_PARAM_SUBTYPE)
    {   //dwSubtype member of CONNMGR_CONNECTION_DETAILED_STATUS is valid
        //DEBUGMSG(1,(L"\tConnSubtype= '%s'\r\n", szConnSubtype[p->dwSubtype]));
        logMsg(L"\tConnSubtype= '%s'\r\n", szConnSubtype[p->dwSubtype]);
        switch(p->dwSubtype){
            case CM_CONNSUBTYPE_UNKNOWN:
                break;
        }
    }
    if(p->dwFlags & CONNMGRDETAILEDSTATUS_PARAM_FLAGS){
        if(p->dwFlags && CM_DSF_BILLBYTIME){
            //DEBUGMSG(1, (L"\t cm_flags+=CM_DSF_BILLBYTIME\r\n"));
            logMsg(L"\t cm_flags+=CM_DSF_BILLBYTIME\r\n");
        }
        if(p->dwFlags && CM_DSF_ALWAYSON){
            //DEBUGMSG(1, (L"\t cm_flags+=CM_DSF_ALWAYSON\r\n"));
            logMsg(L"\t cm_flags+=CM_DSF_ALWAYSON\r\n");
        }
...
void dump_details(CONNMGR_CONNECTION_DETAILED_STATUS *p)
{
    dump_details_params(p);
    return;
    TCHAR txt[MAX_PATH];
    if (p->szAdapterName && wcslen(p->szAdapterName)>0){
        //DEBUGMSG(1,(L"adap: %s\r\n", p->szAdapterName));
        logMsg(L"adap: %s\r\n", p->szAdapterName);
        //wsprintf(txt, L"adap: %s\r\n", p->szAdapterName);
        //addText(hWndMain, txt);
    }
    if (p->szDescription){
        //DEBUGMSG(1, (L"desc: %s\r\n", p->szDescription));
        logMsg(L"desc: %s\r\n", p->szDescription);
        //wsprintf(txt, L"desc: %s\r\n", p->szDescription);
        //addText(hWndMain, txt);
    }
...

deviceMon

deviceMon (work in progress) watches the device for changes in drivers like connect/disconnect, etc.

This logging tool will also use a message queue provided by the MS API set. Here is a small sample watching for a disk change:

...
void MonitorForNewDisks()
{
    HANDLE hNotify;
    HANDLE qStore ;
    DWORD flags;
    DWORD size;
    BYTE DevDetail[sizeof(DEVDETAIL) + (MAX_PATH * sizeof( TCHAR ))];
    DEVDETAIL * pDetail = (DEVDETAIL *)DevDetail;
    MSGQUEUEOPTIONS msgopts;

    msgopts.dwSize = sizeof(MSGQUEUEOPTIONS);
    msgopts.dwFlags = 0;
    msgopts.dwMaxMessages = 0;
    msgopts.cbMaxMessage = sizeof(DevDetail);
    msgopts.bReadAccess = TRUE;

    qStore = CreateMsgQueue(NULL, &msgopts);
/*
"IClass"="{f8a6ba98-087a-43ac-a9d8-b7f13c5bae31}"; This is DEVCLASS_STREAM_GUID
In case you follow my suggestion going for CE_DRIVER_SERIAL_PORT_GUID you will need:
"IClass"="{CC5195AC-BA49-48a0-BE17-DF6D1B0173DD}" ; this is CE_DRIVER_SERIAL_PORT_GUID
*/
    hNotify = RequestDeviceNotifications(&BLOCK_DRIVER_GUID, qStore, TRUE);

    do
    {
        if(WaitForSingleObject(qStore, 5000) == WAIT_OBJECT_0)
        {
            while(ReadMsgQueue(qStore, pDetail, sizeof(DevDetail), &size, 1, &flags))
            {
                if(pDetail->fAttached)
                    ;//do something HandleNewDisk(pDetail->szName);
            }
        }
    } while( !StopMonitoringForNewDisks );
...

memuse

memuse logs the memory usage of all running processes on your device. Possibly find a memory leak in an app.

This logging uses a periodic timer to dump the memory use of all processes. Here, it is useful to know that there are a max of 32 processes running. Each process has its own slot and we can walk the slots and query the memory use. Then, we need to map the process ID to a process name to get a named list:

...
DWORD getVMuse(){
    //build the process list
    int iMax = GetProcessNameList((PROCESSNAMES*) &ProcessNames);

    DWORD total = 0;
    for( int idx = 2; idx < 33; ++idx )
    {
        PROCVMINFO vmi = { 0 };
        if( CeGetProcVMInfo( idx, sizeof( PROCVMINFO ), &vmi ) )
        {
            //DEBUGMSG(1, ( L"%d: 0x08x %d bytes\r\n", idx, vmi.hProc, vmi.cbRwMemUsed ));
            total += vmi.cbRwMemUsed;
            //GetProcessIDFromIndex() and match it to the th32ProcessID member 
            //of the PROCESSENTRY32 structure
            HANDLE dwThreaID = GetProcessIDFromIndex(idx);
            for(int i=0; i<iMax; i++){
                if(ProcessNames[i]._dwID == (DWORD)dwThreaID)
                    ProcessNames[i]._memuse = vmi.cbRwMemUsed;
            }
        }
    }
...

All projects can be loaded from logging_ce at github.