Error logging and debugging

Error logging

Error logging functionality provides means to have evidence of problems that IVD processes encounter during execution. This sort of files are helpful when a problem (read bug) occurs at customer side.

Error logging is used by IVD exceptions as well (ivd_Exception) if a_logError is specified at construction.

Error logging consists of several macros. Most important are:

  1. log_ERR_m(): Write a log entry about a critical error that can't be resolved by the IVD application.
  2. log_WRN_m(): Warning log entry about a situation that is not normal but the application can resolve it and continue.
  3. log_NOTE_m(): Note entry about a situation worth noting but it does not have any influence on the execution or internal state.

See Error logging for details about error logging.

ivd_Exception ivd_SysError ivd_Error ivd_InternalError

Debugging

The purpose of debugging facility that is built into ivdcmn library is to be able to trace binary execution. This feature is turned off by default.

Debugging is mostly useful when a problem is sought. Bear in mind that you will be the one to read the debugging information. Write debugging statements that can help you.

Turning debugging on and off

Debugging can be turned on with three functions:

  1. dbg_On() (uses previously set debugging parameters)
  2. dbg_On(log_DbgLevel_t level, int flags, string filename) (sets new parameters and turns debugging on)
  3. dbg_On(char *argv[], int argc) (sets parameters from command line or environment)

Meaning of the debugging parameters:

  1. level: Is the filter to control the verbosity of the output. It can be one of the: dbg_LOW, dbg_NORM, dbg_EXTAPI, dbg_DETAIL.
  2. flags: OR-ed flags to control the output format. You can use dbg_NOHEADER, dbg_COMPACT, dbg_INOUT, dbg_THROW and dbg_ERRORLOG.
  3. filename (optional): Filename to store debugging information to. cout is used if filename is not specified.

Flag dbg_THROW causes each throw of IVD specific exception to be logged in the debug file if debugging is active.

Flag dbg_ERRORLOG makes a copy of each error log message to be copied to debug file.

How to use debugging from command line?

Use ivd_ParseCmnArgs() and dbg_On(); somewhere at the beginning of the main() to parse the debugging options and to turn it on according to the cli arguments.

Available command line options:

  1. -dbg to specify debugging options, followed by
  2. level: 
        'L' dbg_LOW
    'N' dbg_NORM
    'A' dbg_EXTAPI
    'D' dbg_DETAIL
  3. file name
  4. flags (you can speficy more flags: e.g. INE): 
        'I'    dbg_INOUT   
    'N'    dbg_NOHEADER
    'C'    dbg_COMPACT 
    'T'    dbg_THROW
    'E'    dbg_ERRORLOG

Example:

int main(int argc, char *argv[]) {
    log_FUNC_m(main);

    switch (ivd_ParseCmnArgs(argc, argv)) {
        case ica_HELP:
            cout << "DF unit test." << endl;
            exit(ivd_EC_OK);
        default:;
    }

    dbg_On();

    ut_path();
    ut_thread();

    dbg_Off();
    
    return 0;
}

Sample output of one run: 

***************************************************************
 IVD System debug file

 Created      : 2001/11/19 10:34:16.094
 Hostname (IP): TO DO (TO DO)
 OS           : TO DO (TO DO,TO DO) on TO DO
 IVD build    : TO DO
 Debug params : Detail level: NORM flags: COMPACT, 
***************************************************************

[N 000000.001772 10:34:16.394] Waiting for thread to finish
[N 000000.001576 10:34:16.394] In function MultiFunction. THID:1576
[N 000000.001576 10:34:18.397] Leaving MultiFunction
[N 000000.001772 10:34:18.397] Thread finished.
[N 000000.001772 10:34:18.397] Waiting for thread to finish
[N 000000.001576 10:34:18.407] In function MultiFunction. THID:1576
[N 000000.001576 10:34:20.410] Leaving MultiFunction
[N 000000.001772 10:34:20.410] Thread finished.

***************************************************************
 Debugging completed automatically by destructor. 

***************************************************************
 IVD System debug file completed.
***************************************************************

Adding debugging to the source code

Debugging information is written to the debug file using log_DBG_m() macro. It has two parameters:

  1. level: At which level the message will be displayed.
  2. Debug message in the stream form (using << operator).

Macro log_FUNC_INT_m() is compiled conditionally if log_INT_DEBUG_d define is set. These debug messages can be excluded from the binaries at compile time, but they are useful for development purposes.

log_DBG_m() requires the log_FUNC_m() to be used in that function (or at least log_FUNCTAG_m()) so that it can properly format the output message. There are three macros to specify function's name:

log_DBG_m() consumes no CPU time when debugging is inactive.

Example:

CORBA::Object_var ipc_Corba::Resolve(const string &a_objectName) {
    log_FUNC_m(Resolve);

    if (CORBA::is_nil(m_orb) == true) {
        throw ivd_InternalError(
            ie_IPC_ORB,
            "ORB is not yet initialized. Use Init(argv, argc)",
            true
        );
    }

    try {
        // Resolve the name to an object reference.
        log_DBG_m(dbg_EXTAPI, "Getting object reference of " << a_objectName.c_str());
        CosNaming::Name_var name = omniURI::stringToName(a_objectName.c_str());
        CORBA::Object_var   obj = m_rootContext->resolve(name);
        log_DBG_m(dbg_EXTAPI, "Reference is " << m_orb->object_to_string(obj));

        return obj;
    }
    catch(CosNaming::NamingContext::NotFound& ex) {
    }
    catch(CORBA::COMM_FAILURE& ex) {
    }
    catch(CORBA::SystemException&) {
    }

    return CORBA::Object::_nil();
}

The above example produces the following output:


[N 066370.001772 16:13:29.591] ==> Resolve
[A 066370.001772 16:13:29.591] Getting object reference of path/to/object
omniORB: Invoke 'resolve' on remote: key<0x4e616d6553657276696365>
[A 066370.001772 16:13:29.591] Reference is IOR:01000000010000000000000000000000
[N 066370.001772 16:13:29.591] <== Resolve

Debugging with full header:

[N 066370.001772 16:15:44.666; ipc_Corba::Resolve, ipc_corba.cpp,1.5]
==> Resolve

[A 066370.001772 16:15:44.666; ipc_Corba::Resolve, ipc_corba.cpp,1.5]
Getting object reference of path/to/object

omniORB: Invoke 'resolve' on remote: key<0x4e616d6553657276696365>
[A 066370.001772 16:15:44.666; ipc_Corba::Resolve, ipc_corba.cpp,1.5]
Reference is IOR:01000000010000000000000000000000

[N 066370.001772 16:15:44.666; ipc_Corba::Resolve, ipc_corba.cpp,1.5]
<== Resolve

Debugging with no header:

==> Resolve
Getting object reference of path/to/object
omniORB: Invoke 'resolve' on remote: key<0x4e616d6553657276696365>
Reference is IOR:01000000010000000000000000000000
<== Resolve
Generated on Mon Feb 27 18:52:17 2012 for OPENARCHIVE by  doxygen 1.5.6