Click here to Skip to main content
15,868,016 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 
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 
My observation is that logging in general is usually over-engineered for no beneficial reason. It's fine throwing a ton of complexity at a problem if there are clear benefits to doing so.

Why have different categories? What benefit does having different dynamic categories possible add to software logs?

When something goes wrong you are going to examine all the log entries regardless of categories anyway, and in practice DEBUG and TRACE just never get used because if something is important enough to log it gets done regardless of the assumed severity of the condition. If it isn't important no developer bothers putting it into DEBUG or TRACE categories.

Why do log entries need a unique ID? What benefit can someone get out of each log entry having a unique ID?

Besides, why not just use the current time so that post-problem investigation can link the estimated time the problem occurred with the entries in the log file.

In what scenario is is helpful to have a unique ID for the log entry, but not the combination of logfile-name + line-number + timestamp?

The point of logging is to have enough useful data after an issue is reported to determine the steps leading up to the issue and, if possible, the cause of the issue. There is no problem with erring on the side of slightly too much information because even a 20GB logfile is still quickly searchable, and on some systems the logfiles are rotated anyway so that each logfile spans only a single day.

I worked on software for munitions and explosives. My logging there was to ensure we knew what happened if something went boom when it wasn't supposed to (or, did not go boom when it was supposed to), so obviously not desktop/pc/server software.

My preferred log utility that I used in human life-critical software (and still do) is something like this:


#define WARN(...)       do {\
   fprintf (logfile_pointer, "%zu [%s:%i] WARNING: ", (size_t)time (NULL)__FILE__, __LINE__);\
   fprintf (logfile_pointer, __VA_ARGS__);\
} while (0)

#define ERROR(...)       do {\
   fprintf (logfile_pointer, "%zu [%s:%i] ERROR:", (size_t)time (NULL), __FILE__, __LINE__);\
   fprintf (logfile_pointer, __VA_ARGS__);\
} while (0)

// Example usage:
if (!(fhandle = fopen (fname, "rt")) {
   WARN ("Unable to open configuration %s for reading - %m\nUsing defaults instead.\n", fname);
}

if ((errcode = critical_func ())!=EXIT_SUCCESS) {
   ERROR ("critical_func() returned error [%i], aborting.\n", errcode);
}


The software, on startup and a once-a-day timer, will open the correct filename and set that global logfile_pointer to the file. When incidence reports came in, they had a approx time and date of the incident. This let us restrict our logfile examination to those hours when it could have possibly happened.

The logging facility you have, even though over-engineered, does not let the problem investigator match up the problem report time to the log entries time. It gives them IDs, which don't help them, and categories of which only two will ever be looked at and/or used.

It also doesn't, as far as I can tell, allow the developer to write logs that output program variable values within the message they way my examples above do. There's no point in logging "Could not open file" if you cannot embed the filename and the reason for being unable to open the file (like my simple example WARN() does above).
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.