Click here to Skip to main content
15,867,778 members
Articles / Programming Languages / Objective C

Dynamic Logging

Rate me:
Please Sign up or sign in to vote.
3.50/5 (3 votes)
12 Jan 2021CPOL5 min read 11.3K   96   6   7
Concept, Motivation and Implementation of Dynamic Logging - a valuable aid to the C++ programmer
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 and not pay a price for this freedom. On the other hand, we would like to evade over-flooding of the log file.

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:

C++
MyLog("<the message>");

Which simply writes to a log file:

C++
<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.

C++
{
  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:

C++
#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:

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

For example:

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

Represented in a configuration file:

C++
0 MyClass::DoIt
0 MyClass::DoIt.Leave

To NOT log either of these entries,

OR

changing to 1 and re-loading the configuration file:

C++
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:

C++
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:

C++
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):

C++
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:

C++
#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:

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

will produce the following for VC++ on Windows:

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

and the following for g++ on Linux:

C++
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):

C++
0 f
0 f<char*>
0 f<int>

And on Linux:

C++
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

  • 30th December, 2020: Initial version

License

This article, along with any associated source code and files, is licensed under The Code Project Open License (CPOL)


Written By
Software Developer (Senior)
Israel Israel
M.Sc. in Computer Science.
C/C++ specialist.
Specializing in infrastructure and system analysis.

Comments and Discussions

 
GeneralMy vote of 3 Pin
SeattleC++18-Jan-21 13:08
SeattleC++18-Jan-21 13:08 
QuestionYALS (Yet Another Logging Subsystem) sigh Pin
SeattleC++18-Jan-21 13:07
SeattleC++18-Jan-21 13:07 
AnswerRe: YALS (Yet Another Logging Subsystem) sigh Pin
Alexander Schichmanter27-Jan-21 19:41
Alexander Schichmanter27-Jan-21 19:41 
I appreciate the lengthy and thoughtful comment. I must disagree at some and explain another points remained unclear.


Quote:
One thing a logging subsystem needs to get right is to minimize the cost logging adds to the running program when it is turned off. It may be necessary to add voluminous logging when looking for some difficult-to-find bug. But we don't want to pay the cost to format all that detail unless we are going to actually use it, because it slows the running program down. Building readable strings for output is a notoriously expensive process.


I agree with every word. It seems I failed to present the point.

Let's look at the following example:
Given a very time consuming func to create a very complex message based on many params

C++
char* CallAFuncToReturnErrMessage(MyType* p1, MyType* p2, ...)
{
  std::string s;
  // construct s according to input - lengthy, time-consuming process

  return s.c_str();
}


Then, using DYNALOG the function is only called if the flag is on. If (even in runtime) we turn the flag off, no cost is paid.

DYNALOG("<namespace::class::func.location>", CallAFuncToReturnErrMessage(param1, param2, ...));

I do believe tis is what you were so anxious to see.



Quote:
Here we are, well into the 21st century. Can we please run away screaming from solutions that involve the C preprocessor? Please? I have experience with several macro-wrapped logging subsystems. They are all cranky to use for any but the most minimal logs. Do you put a semicolon after the MYLOG(...), or don't you? Can you understand the macro to debug its expansion? What fraction of developers understand the purpose of that do {...} while(false); anyway?


Well, I am a C++ programmer, but there is a reason C macros are still with us. This is a perfect illustration of their existence justification. Via the macro system we are able to propose a convenient, simple and self-explanatory syntax for the programmer. It is not possible to achieve otherwise.

Quote:
What fraction of developers understand the purpose of that do {...} while(false); anyway?


They don't have to. You are supposed to write normal code, following the convention that every C statement is terminated by a ;.
And, regarding the do-while, well, you can google it up to see the reasoning behind it (hint - there is a real purpose for that syntax). In a nutshell - it is intended to disallow complex if statements that will one day break, issuing a compilation error instead.



Quote:
A logging subsystem is vastly more useful if it can send the log to a variety of places. Windows debug window, standard output, file (with deletion of old logs), or UDP address for collection by an external process. Even better if you can select a combination of these places.


It is trivial to expand the macro to do all of those things. The main task - creating the msg only if requested is achieved. Now you can send it anywhere you like. In the real world we implemented a log file and a logging thread which actually sends it to a UDP port.


Quote:
So, nice start, but you probably needn't have bothered. A few minutes with google is your friend. It took me years to understand that.


Trust me. I googled like madman. As far as I know, this is a unique solution. Please prove me wrong, I am always willing to learn more.

modified 7-Feb-21 2:30am.

GeneralMy vote of 4 Pin
steppeman4-Jan-21 6:51
steppeman4-Jan-21 6:51 
GeneralRe: My vote of 4 Pin
Alexander Schichmanter4-Jan-21 21:16
Alexander Schichmanter4-Jan-21 21:16 
QuestionLogging in general ... Pin
Member 1330167931-Dec-20 0:15
Member 1330167931-Dec-20 0:15 
AnswerRe: Logging in general ... Pin
Member 1307569831-Dec-20 3:20
Member 1307569831-Dec-20 3:20 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Praise Praise    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.