Ignore:
Timestamp:
Feb 1, 2012, 2:43:43 PM (14 years ago)
Author:
dmik
Message:

Print human readable time stamp in log files.

Also clean up the code and format so that the prefix
has permanent alignment and takes less space.

File:
1 edited

Legend:

Unmodified
Added
Removed

  • trunk/src/kernel32/dbglog.cpp

    r21916 r21957  
    256256static FILE *flog = NULL;   /*PLF Mon  97-09-08 20:00:15*/
    257257static BOOL init = FALSE;
     258static BOOL firstTime = FALSE;
    258259static BOOL fLogging = TRUE;
    259260static int  dwEnableLogging = 1;
    … …  
    294295#endif
    295296
     297#ifdef LOG_TIME
     298static DWORD startTicks = 0;
     299static DWORD startTime = 0;
     300VOID WINAPI GetLocalTime(LPSYSTEMTIME);
     301#endif
     302
    296303static void win32modname (ULONG eip, char *szModName, int cbModName)
    297304{
    … …  
    310317int SYSTEM WriteLog(const char *tekst, ...)
    311318{
    312   USHORT  sel = RestoreOS2FS();
    313   va_list argptr;
    314   TEB *teb = GetThreadTEB();
    315 
    316   pszLastLogEntry = tekst;
    317 
    318   ODIN_HEAPCHECK();
    319 
    320   if(!init)
    321   {
    322     init = TRUE;
    323 
    324     if(getenv("WIN32LOG_FLUSHLINES")) {
    325         fFlushLines = TRUE;
    326     }
     319    USHORT  sel = RestoreOS2FS();
     320    va_list argptr;
     321    TEB *teb = GetThreadTEB();
     322
     323    pszLastLogEntry = tekst;
     324
     325    ODIN_HEAPCHECK();
     326
     327    if (!init)
     328    {
     329        init = TRUE;
     330        firstTime = TRUE;
     331
     332#ifdef LOG_TIME
     333        // initialize the current time counter
     334        startTicks = GetTickCount();
     335        SYSTEMTIME t;
     336        GetLocalTime(&t);
     337        startTime = t.wHour * 3600 + t.wMinute * 60 + t.wSecond;
     338        startTime = (startTime * 1000) + t.wMilliseconds;
     339#endif
     340
     341        if(getenv("WIN32LOG_FLUSHLINES"))
     342            fFlushLines = TRUE;
     343
    327344#ifdef DEFAULT_LOGGING_OFF
    328     if(getenv("WIN32LOG_ENABLED")) {
    329 #else
    330     if(!getenv("NOWIN32LOG")) {
    331 #endif
    332 
     345        if(getenv("WIN32LOG_ENABLED"))
     346        {
     347#else
     348        if(!getenv("NOWIN32LOG"))
     349        {
     350#endif
    333351#ifdef WIN32_IP_LOGGING
    334         char *logserver = getenv("WIN32LOG_IPSERVER");
    335         if(logserver) {
    336              sock_init();
    337 
    338              memset(&servername, 0, sizeof(servername));
    339              servername.sin_family      = AF_INET;
    340              servername.sin_addr.s_addr = inet_addr(logserver);
    341              servername.sin_port        = WIN32_IP_LOG_PORT;
    342 
    343              logSocket = socket(PF_INET, SOCK_DGRAM, 0);
     352            char *logserver = getenv("WIN32LOG_IPSERVER");
     353            if(logserver) {
     354                sock_init();
     355
     356                memset(&servername, 0, sizeof(servername));
     357                servername.sin_family      = AF_INET;
     358                servername.sin_addr.s_addr = inet_addr(logserver);
     359                servername.sin_port        = WIN32_IP_LOG_PORT;
     360
     361                logSocket = socket(PF_INET, SOCK_DGRAM, 0);
     362            }
     363#endif
     364            char szLogFile[CCHMAXPATH];
     365            const char *pszLogBase = getenv("WIN32LOG_FILEBASE");
     366            if (!pszLogBase)
     367                pszLogBase = "odin32_";
     368
     369            sprintf(szLogFile, "%s%d.log", pszLogBase, getpid());
     370            flog = fopen(szLogFile, "w");
     371            if(flog == NULL)
     372            {//probably running exe on readonly device
     373                sprintf(szLogFile, "%sodin32_%d.log", kernel32Path, getpid());
     374                flog = fopen(szLogFile, "w");
     375            }
     376#ifdef __IBMC__
     377            oldcrtmsghandle = _set_crt_msg_handle(fileno(flog));
     378#endif
    344379        }
    345 #endif
    346         char szLogFile[CCHMAXPATH];
    347         const char *pszLogBase = getenv("WIN32LOG_FILEBASE");
    348         if (!pszLogBase)
    349             pszLogBase = "odin32_";
    350 
    351         sprintf(szLogFile, "%s%d.log", pszLogBase, getpid());
    352         flog = fopen(szLogFile, "w");
    353         if(flog == NULL)
    354         {//probably running exe on readonly device
    355             sprintf(szLogFile, "%sodin32_%d.log", kernel32Path, getpid());
    356             flog = fopen(szLogFile, "w");
     380        else
     381            fLogging = FALSE;
     382
     383        fDisableThread[0] = getenv("DISABLE_THREAD1") != NULL;
     384        fDisableThread[1] = getenv("DISABLE_THREAD2") != NULL;
     385        fDisableThread[2] = getenv("DISABLE_THREAD3") != NULL;
     386        fDisableThread[3] = getenv("DISABLE_THREAD4") != NULL;
     387        fDisableThread[4] = getenv("DISABLE_THREAD5") != NULL;
     388    }
     389
     390    if (teb)
     391    {
     392        if(teb->o.odin.threadId < 5 && fDisableThread[teb->o.odin.threadId-1] == 1)
     393        {
     394            SetFS(sel);
     395            return 1;
    357396        }
    358 #ifdef __IBMC__
    359         oldcrtmsghandle = _set_crt_msg_handle(fileno(flog));
    360 #endif
    361     }
    362     else
    363       fLogging = FALSE;
    364 
    365     fDisableThread[0] = getenv("DISABLE_THREAD1") != NULL;
    366     fDisableThread[1] = getenv("DISABLE_THREAD2") != NULL;
    367     fDisableThread[2] = getenv("DISABLE_THREAD3") != NULL;
    368     fDisableThread[3] = getenv("DISABLE_THREAD4") != NULL;
    369     fDisableThread[4] = getenv("DISABLE_THREAD5") != NULL;
    370   }
    371 
    372   if(teb) {
    373       if(teb->o.odin.threadId < 5 && fDisableThread[teb->o.odin.threadId-1] == 1) {
    374           SetFS(sel);
    375           return 1;
    376       }
    377   }
    378 
    379   if(!tekst) {
    380     if(flog) fflush( flog);
    381     SetFS(sel);
    382     return 1;
    383   }
    384 
    385   if(fLogging && flog && (dwEnableLogging > 0))
    386   {
    387     va_start(argptr, tekst);
     397    }
     398
     399    if (!tekst)
     400    {
     401        if (flog)
     402            fflush( flog);
     403        SetFS(sel);
     404        return 1;
     405    }
     406
     407#ifdef LOG_TIME
     408        // get human readable time values
     409        DWORD time = startTime + (GetTickCount() - startTicks);
     410        DWORD h = time / 3600000;
     411        DWORD m = (time %= 3600000) / 60000;
     412        DWORD s = (time %= 60000) / 1000;
     413        DWORD ms = time % 1000;
     414#endif
     415
     416    if (fLogging && flog && (dwEnableLogging > 0))
     417    {
     418        if (firstTime)
     419        {
     420            firstTime = FALSE;
     421
     422            // print the header with the legend
     423#ifdef LOG_TIME
     424                fprintf(flog,
     425                        " /--------------------- Thread ID\n"
     426                        " |   /----------------- Call Depth\n"
     427                        " |   |  /-------------- Flags (O = OS/2 mode (FS=150B))\n"
     428                        " |   |  |      /------- Current Time\n"
     429                        "--- --- - ------------\n");
     430#else
     431#ifdef SHOW_FPU_CONTROLREG
     432                fprintf(flog,
     433                        " /------------ Thread ID\n"
     434                        " |   /-------- Call Depth\n"
     435                        " |   |  /----- Flags (O = OS/2 mode (FS=150B))\n"
     436                        " |   |  |  /-- FPU Control Register\n"
     437                        "--- --- - ---\n");
     438#else
     439                fprintf(flog,
     440                        " /-------- Thread ID\n"
     441                        " |   /---- Call Depth\n"
     442                        " |   |  /- Flags (O = OS/2 mode (FS=150B))\n"
     443                        "--- --- -\n");
     444#endif
     445#endif
     446        }
     447
     448        va_start(argptr, tekst);
    388449
    389450#ifdef WIN32_IP_LOGGING
    390     if(logSocket == -1) {
    391 #endif
    392     if(teb)
    393     {
    394       ULONG ulCallDepth;
     451        if (logSocket == -1)
     452        {
     453#endif
     454            if (teb)
     455            {
     456                ULONG ulCallDepth;
    395457#ifdef DEBUG
    396       ulCallDepth = teb->o.odin.dbgCallDepth;
    397 #else
    398       ulCallDepth = 0;
    399 #endif
    400 
    401       teb->o.odin.logfile = (DWORD)flog;
     458                ulCallDepth = teb->o.odin.dbgCallDepth;
     459#else
     460                ulCallDepth = 0;
     461#endif
     462
     463                teb->o.odin.logfile = (DWORD)flog;
    402464
    403465#ifdef LOG_TIME
    404       if(sel == 0x150b && fSwitchTIBSel)
    405         fprintf(flog,
    406                 "t%02d (%3d): (%x) (FS=150B) ",
    407                 LOWORD(teb->o.odin.threadId),
    408                 ulCallDepth,
    409                 GetTickCount());
    410       else
    411         fprintf(flog,
    412                 "t%02d (%3d): (%x) ",
    413                 LOWORD(teb->o.odin.threadId),
    414                 ulCallDepth,
    415                 GetTickCount());
    416 #else
    417       if(sel == 0x150b && fSwitchTIBSel)
    418         fprintf(flog,
     466                fprintf(flog,
     467                        "t%02d %03d %c %02d:%02d:%02d.%03d: ",
     468                        LOWORD(teb->o.odin.threadId),
     469                        ulCallDepth,
     470                        (sel == 0x150b && fSwitchTIBSel) ? 'O' : '-',
     471                        h, m, s, ms);
     472#else
    419473#ifdef SHOW_FPU_CONTROLREG
    420                 "t%02d (%3d)(%3x): ",
    421                 LOWORD(teb->o.odin.threadId),
    422                 ulCallDepth,
    423                 CONTROL87(0,0));
    424 #else
    425                 "t%02d (%3d): (FS=150B) ",
    426                 LOWORD(teb->o.odin.threadId),
    427                 ulCallDepth);
    428 #endif
    429       else
    430         fprintf(flog,
     474                fprintf(flog,
     475                        "t%02d %03d %c %03X: ",
     476                        LOWORD(teb->o.odin.threadId),
     477                        ulCallDepth,
     478                        (sel == 0x150b && fSwitchTIBSel) ? 'O' : '-',
     479                        CONTROL87(0,0));
     480#else
     481                fprintf(flog,
     482                        "t%02d %03d %c: ",
     483                        LOWORD(teb->o.odin.threadId),
     484                        ulCallDepth,
     485                        (sel == 0x150b && fSwitchTIBSel) ? 'O' : '-');
     486#endif
     487#endif
     488            }
     489            else
     490            {
     491#ifdef LOG_TIME
     492                fprintf(flog,
     493                        "tXX ??? ? %02d:%02d:%02d.%03d: ",
     494                        h, m, s, ms);
     495#else
    431496#ifdef SHOW_FPU_CONTROLREG
    432                 "t%02d (%3d)(%3x): ",
    433                 LOWORD(teb->o.odin.threadId),
    434                 ulCallDepth,
    435                 CONTROL87(0,0));
    436 #else
    437                 "t%02d (%3d): ",
    438                 LOWORD(teb->o.odin.threadId),
    439                 ulCallDepth);
    440 #endif
    441 #endif
    442     }
     497                fprintf(flog,
     498                        "tXX ??? ? ???: ");
     499#else
     500                fprintf(flog,
     501                        "tXX ??? ?: ");
     502#endif
     503#endif
     504            }
     505#ifdef WIN32_IP_LOGGING
     506        }
     507#endif
     508
     509#ifdef WIN32_IP_LOGGING
     510        if(logSocket != -1)
     511        {
     512            char logbuffer[1024];
     513            int  prefixlen = 0;
     514
     515            if (teb)
     516            {
     517                ULONG ulCallDepth;
     518#ifdef DEBUG
     519                ulCallDepth = teb->o.odin.dbgCallDepth;
     520#else
     521                ulCallDepth = 0;
     522#endif
    443523#ifdef LOG_TIME
    444     else {
    445         fprintf(flog, "tX: (%x) ", GetTickCount());
    446     }
    447 #endif
    448 #ifdef WIN32_IP_LOGGING
    449     }
    450 #endif
    451 
    452 #ifdef WIN32_IP_LOGGING
    453     if(logSocket != -1) {
    454         char logbuffer[1024];
    455         int  prefixlen = 0;
    456 
    457         if(teb)
     524                sprintf(logbuffer,
     525                        "t%02d %03d %02d:%02d:%02d.%03d [%c]: ",
     526                        LOWORD(teb->o.odin.threadId),
     527                        ulCallDepth,
     528                        h, m, s, ms,
     529                        (sel == 0x150b && fSwitchTIBSel) ? 'O' : '.');
     530#else
     531                sprintf(logbuffer,
     532                        "t%02d %03d [%c]: ",
     533                        LOWORD(teb->o.odin.threadId),
     534                        ulCallDepth,
     535                        (sel == 0x150b && fSwitchTIBSel) ? 'O' : '.');
     536#endif
     537                prefixlen = strlen(logbuffer);
     538            }
     539
     540            vsprintf(&logbuffer[prefixlen], tekst, argptr);
     541
     542            int rc;
     543
     544            servername.sin_family      = AF_INET;
     545            servername.sin_port        = WIN32_IP_LOG_PORT;
     546
     547            rc = sendto(logSocket, logbuffer, strlen(logbuffer)+1, 0, (struct sockaddr *)&servername, sizeof(servername));
     548            if (rc == -1)
     549                rc = sock_errno();
     550            if (teb)
     551                teb->o.odin.logfile = 0;
     552            va_end(argptr);
     553        }
     554        else
    458555        {
    459             ULONG ulCallDepth;
    460 #ifdef DEBUG
    461             ulCallDepth = teb->o.odin.dbgCallDepth;
    462 #else
    463             ulCallDepth = 0;
    464 #endif
    465 #ifdef LOG_TIME
    466             if(sel == 0x150b && fSwitchTIBSel)
    467                 sprintf(logbuffer, "t%02d (%3d): %x (FS=150B) ",
    468                         LOWORD(teb->o.odin.threadId), ulCallDepth, GetTickCount());
    469             else
    470                 sprintf(logbuffer, "t%02d (%3d): %x ",
    471                         LOWORD(teb->o.odin.threadId), ulCallDepth, GetTickCount());
    472 #else
    473             if(sel == 0x150b && fSwitchTIBSel)
    474                 sprintf(logbuffer, "t%02d (%3d): (FS=150B) ",
    475                         LOWORD(teb->o.odin.threadId), ulCallDepth);
    476             else
    477                 sprintf(logbuffer, "t%02d (%3d): ",
    478                         LOWORD(teb->o.odin.threadId), ulCallDepth);
    479 #endif
    480             prefixlen = strlen(logbuffer);
     556            vfprintf(flog, tekst, argptr);
     557            if (teb)
     558                teb->o.odin.logfile = 0;
     559            va_end(argptr);
     560
     561            if (tekst[strlen(tekst)-1] != '\n')
     562                fprintf(flog, "\n");
     563#if 0
     564            if (teb && LOWORD(teb->o.odin.threadId) > 1)
     565            {
     566                TEB *winteb = GetThreadTEB();
     567                PWINEXCEPTION_FRAME pframe = (PWINEXCEPTION_FRAME)winteb->except;
     568
     569                fprintf(flog, "debug Win32 exception chain %08X (%08X) (teb = %08X, esp = %08X)\n", pframe, QueryExceptionChain(), teb, getESP());
     570                fprintf(flog, "Top record at %08X, Prev at %08X, handler at %08X\n", (PWINEXCEPTION_FRAME)QueryExceptionChain(), ((PWINEXCEPTION_FRAME)QueryExceptionChain())->Prev, ((PWINEXCEPTION_FRAME)QueryExceptionChain())->Handler);
     571                fprintf(flog, "*teb %08X %08X %08X %08X %08X %08X %08X %08X\n",
     572                        ((ULONG *)teb)[0],((ULONG *)teb)[1],((ULONG *)teb)[2],((ULONG *)teb)[3],
     573                        ((ULONG *)teb)[4],((ULONG *)teb)[5],((ULONG *)teb)[6],((ULONG *)teb)[7]);
     574                while ((pframe != NULL) && ((ULONG)pframe != 0xFFFFFFFF)) {
     575                    if ((void *)pframe > winteb->stack_top || (void *)pframe < winteb->stack_low)
     576                    {
     577                        fprintf(flog, "Chain corrupted! Record at %08X is outside stack boundaries!\n", pframe);
     578                        break;
     579                    }
     580
     581                    if ((ULONG)pframe < getESP())
     582                    {
     583                        fprintf(flog, "Chain corrupted! Record at %08X is below stack pointer!\n", pframe);
     584                        break;
     585                    }
     586
     587                    char szModName[32] = "";
     588                    char szModName2[32] = "";
     589                    win32modname ((ULONG)pframe->Handler, szModName, sizeof (szModName));
     590                    win32modname ((ULONG)pframe->Prev, szModName2, sizeof (szModName2));
     591                    fprintf(flog, "Record at %08X, Prev at %08X [%s], handler at %08X [%s]\n", pframe, pframe->Prev, szModName2, pframe->Handler, szModName);
     592                    if (pframe == pframe->Prev) {
     593                        fprintf(flog, "Chain corrupted! Record at %08X pointing to itself!\n", pframe);
     594                        break;
     595                    }
     596                    pframe = pframe->Prev;
     597                }
     598            }
     599#endif
     600            if (fFlushLines)
     601                fflush(flog);
    481602        }
    482 
    483         vsprintf(&logbuffer[prefixlen], tekst, argptr);
    484 
    485         int rc;
    486 
    487         servername.sin_family      = AF_INET;
    488         servername.sin_port        = WIN32_IP_LOG_PORT;
    489 
    490         rc = sendto(logSocket, logbuffer, strlen(logbuffer)+1, 0, (struct sockaddr *)&servername, sizeof(servername));
    491         if(rc == -1) {
    492             rc = sock_errno();
    493         }
    494         if(teb) teb->o.odin.logfile = 0;
    495         va_end(argptr);
    496     }
    497     else {
     603#else
    498604        vfprintf(flog, tekst, argptr);
    499605        if(teb) teb->o.odin.logfile = 0;
    … …  
    502608        if(tekst[strlen(tekst)-1] != '\n')
    503609            fprintf(flog, "\n");
    504 #if 0
    505 if (teb && LOWORD(teb->o.odin.threadId) > 1)
    506 {
    507   TEB *winteb = GetThreadTEB();
    508   PWINEXCEPTION_FRAME pframe = (PWINEXCEPTION_FRAME)winteb->except;
    509 
    510   fprintf(flog, "debug Win32 exception chain %08X (%08X) (teb = %08X, esp = %08X)\n", pframe, QueryExceptionChain(), teb, getESP());
    511   fprintf(flog, "Top record at %08X, Prev at %08X, handler at %08X\n", (PWINEXCEPTION_FRAME)QueryExceptionChain(), ((PWINEXCEPTION_FRAME)QueryExceptionChain())->Prev, ((PWINEXCEPTION_FRAME)QueryExceptionChain())->Handler);
    512   fprintf(flog, "*teb %08X %08X %08X %08X %08X %08X %08X %08X\n",
    513           ((ULONG *)teb)[0],((ULONG *)teb)[1],((ULONG *)teb)[2],((ULONG *)teb)[3],
    514           ((ULONG *)teb)[4],((ULONG *)teb)[5],((ULONG *)teb)[6],((ULONG *)teb)[7]);
    515   while ((pframe != NULL) && ((ULONG)pframe != 0xFFFFFFFF)) {
    516         if ((void *)pframe > winteb->stack_top || (void *)pframe < winteb->stack_low)
    517         {
    518             fprintf(flog, "Chain corrupted! Record at %08X is outside stack boundaries!\n", pframe);
    519             break;
    520         }
    521 
    522         if ((ULONG)pframe < getESP())
    523         {
    524             fprintf(flog, "Chain corrupted! Record at %08X is below stack pointer!\n", pframe);
    525             break;
    526         }
    527 
    528         char szModName[32] = "";
    529         char szModName2[32] = "";
    530         win32modname ((ULONG)pframe->Handler, szModName, sizeof (szModName));
    531         win32modname ((ULONG)pframe->Prev, szModName2, sizeof (szModName2));
    532         fprintf(flog, "Record at %08X, Prev at %08X [%s], handler at %08X [%s]\n", pframe, pframe->Prev, szModName2, pframe->Handler, szModName);
    533         if (pframe == pframe->Prev) {
    534             fprintf(flog, "Chain corrupted! Record at %08X pointing to itself!\n", pframe);
    535             break;
    536         }
    537         pframe = pframe->Prev;
    538   }
    539 }
    540 #endif
     610
    541611        if(fFlushLines)
    542612            fflush(flog);
    543     }
    544 #else
    545     vfprintf(flog, tekst, argptr);
    546     if(teb) teb->o.odin.logfile = 0;
    547     va_end(argptr);
    548 
    549     if(tekst[strlen(tekst)-1] != '\n')
    550       fprintf(flog, "\n");
    551 
    552     if(fFlushLines)
    553       fflush(flog);
    554 #endif
    555   }
    556   SetFS(sel);
    557   return 1;
     613#endif
     614    }
     615
     616    SetFS(sel);
     617    return 1;
    558618}
    559619//******************************************************************************
Note: See TracChangeset for help on using the changeset viewer.