Dynamic Logging

• Download source - 1.3 KB

Background

Debugging is (sometimes) heavily based on intelligent logging messages. This statement poses a tradeoff conflict – on the one hand, we would like to write as much data as possible to the log file. On the other hand, we would like to evade over-flooding of the log file.

The standard resolution of this is:

1. Categorization of logging level - typically: Fatal (F), Error (E), Warning (W), Info (I), Debug (D), Trace (T)
2. A complementary approach (on top of the categorization attitude) is defining a level of logging - typically implemented for D, rarely for I, almost never for other categories.

This path of action poses several problematic constraints:

1. All logging has to be decided upon at coding-time, with respect to a). This issue, is however quite logical and acceptable for F/E/W/and even I, is not acceptable for D. Thus, to add or remove D logging means changing the code and re-compilation, an option normally not available at customer site.
2. Supporting b) imposes on the programmer the heavy task of scrupulous design of the messaging hierarchy, trying to correctly predict the actual needs at run-time during most possible scenarios. Moreover, the coding becomes tedious, requiring every message to be wrapped in an if-block checking against the logging level.
3. Any change of setup (e.g., logging level) requires a re-run.
4. A change in the scenario, especially an unexpected one (this is the common case, because when all’s well D logging is near to obsolete, anyway), might (as frequently is the case) prove the debugging level inaccurate. This quickly leads to D-hell.

Definition of Needs

We would like to devise a solution which will remedy the above mentioned deficiencies. The basic requirements are:

1. Debugging granularity - ability to choose which D log messages are actually reported at run time
   1. Each message neeeds to be recognizable in a user-friendly way
   2. Each message should be turnable On/Off
2. Ease of coding
3. An easy identification of the D log message, to support a
4. Automation of c

Proposed Solution

Luckily, all of the needs defined can be fulfilled, using a set of classes and C macros.

Given your favorite standard logging utility, say:

MyLog("<the message>");

Which simply writes to a log file:

<the message>

Suppose that every D logging entry in the code was replaced with a block. Within a block, a unique id is assigned to that message, based on the unique string identifier. Thus, D log messages with the same string identifier same will be assigned the same id. That unique id is checked-for in a singleton to decide whether logging (= reporting) is defined for that id. If that id is registered for logging the standard MyLog is used, imposing all the existing logic within, such as the string construction and the actual decision of reporting to log file, based on configuration read from the XML. Otherwise, nothing happens.

{
  static int i = -1;

  const char* sDynalogId = "<namespace::class::func.location>";

  if (-1 == i)

  {
    i = AddReportable(sDynalogId);
  }

  if (IsReportable(i))
  {
    MyLog(sDynalogId << ": " << "<the message>");
  }
}

Now, though this is functional, it is very cumbersome, to say the least. Given a macro to wrap that code:

#define DYNALOG(_Src, ...) \
  do { \
    static int i = -1; \
    if (-1 == i) \
    { \
      i = NDYNALOG::AddReportable(_Src, false); \
    } \
    if (NDYNALOG::IsReportable(i)) \
    { \
      MyLog(_Src << ": " << __VA_ARGS__); \
    } \
  } while(0)

The above code becomes:

DYNALOG("<namespace::class::func.location>", "<the message>");

For example:

void MyClass::DoIt()
{
  DYNALOG("MyClass::DoIt", "Entered");
  // Do something
 DYNALOG("MyClass::DoIt.Leave", "Exited");
}

Represented in a configuration file:

0 MyClass::DoIt
0 MyClass::DoIt.Leave

To NOT log either of these entries,

OR

changing to 1 and re-loading the configuration file:

0 MyClass::DoIt
1 MyClass::DoIt.Leave

To LOG only the "Exited" message.

So far, we dealt with the single message.

Now, let’s fill in the missing parts. First of all, we need the ability to load/save the dynalog configuration set. Namely:

void NDYNALOG::SaveConfiguration();
void NDYNALOG::LoadConfiguration();

The NDYNALOG::LoadConfiguration is expected to be called when application starts (along with the MyLog initialization). It is also expected to be called when an altered configuration is needed.

The NDYNALOG::SaveConfiguration is expected to be called on application termination, to save the configuration to be loaded on next run. It is also expected to be called when the user wishes to update the configuration list.

Caveats and Solutions

Scenario a

Consider the following code snippet:

void f()
{
  for (int i = 1; i < 3; i++)
  {
    <code>DYNALOG</code>("f", i);
  }
}

Though the expected output is:

f: 1
f: 2
f: 3

A rather surprising output, similar to the following is generated:

f: 72
f: 72
f: 72

The reason is that i in the DYNALOG is obscured by the i inside the macro, which represents the unique id of the message.

The practical solution to this obscenity is to change the i inside the macro to a truly unique name, e.g., __ID_898CC116_D331_4b2e_9E30_952D99CD08D9, s.t. a situation in which it conflicts with the users’ name it falls into the category of “there is no such thing as a foolproof system, because fools are so ingenious”. A definition of a variable in production code by the obscure name of __ID_898CC116_D331_4b2e_9E30_952D99CD08D9 is no less than a malicious sabotage.

Scenario b

Consider the following code snippet (after caveat of Scenario a has been resolved):

template <T> void f(T v)
{
  DYNALOG("f", v);
}

void main()
{
      int i = 123;
      char* s = "Hello";

      f(i);
      f(s);
}

The output is:

f: 123
f: Hello

This does not supply enough information regarding the actual function called (either the int or char* template one). Even worse, there is only one entry in the configuration – f, disallowing differentiation between the function variants. It gets worse, if new function variants are created (e.g.: double, float, std::string) there is no way to define a different behavior for them. It is either log all variant of f, or none.

To solve this, the _FUNC_DECORATED_ macro is supplied:

#ifdef WIN32
#define _FUNC_DECORATED_(_Src) (std::string(__FUNCTION__) + _Src).c_str()
#else // Linux
#define _FUNC_DECORATED_(_Src) (std::string(__PRETTY_FUNCTION__) + _Src).c_str()
#endif

The reason that __func is not used is that __func resolves to f.

The reason windows/linux variations are presented is that __FUNCTION__ in Linux resolves to __func.

Using the suggested macro:

template <T> void f(T v)
{
  DYNALOG(_FUNC_DECORATED_(""), v);
}

will produce the following for VC++ on Windows:

f<int>: 123
f<char*>: Hello

and the following for g++ on Linux:

void f(T) [with T = int]: 123
void f(T) [with T = char*]: Hello

Implementation Issues

The configuration file saved/loaded is a text file, editable in Notepad. Every message unique log tag is on a separate line, where the first field is a Boolean expressing whether logging is required. The rest of the line is the tag for which logging is controlled.

Though entries to the file may be added manually, it is discouraged, because the chance to err is high. The advisable practice is to run the application to allow it to collect the tags into the cache and then perform a Save DYNALOG Configuration action.

Sample configuration file saved/loaded is of the following format (on Windows):

0 f
0 f<char*>
0 f<int>

And on Linux:

0 f
0 void f(T) [with T = char*]
0 void f(T) [with T = int]

In order for DYNALOG to become of valuable aid in the debugging process – programmers are expected to use the tool heavily (since its’ cost in performance in negligible), applying the attitude of “the more – the merrier”.

History

• 30^th December, 2020: Initial version