Uploaded image for project: 'Qpid Proton'
  1. Qpid Proton
  2. PROTON-2245

Logging issues in messenger.c

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Open
    • Major
    • Resolution: Unresolved
    • proton-c-0.31.0
    • None
    • proton-c
    • None

    Description

      With the new QPID Proton library 0.31 to which we upgraded, the application can control the logging via the subsystem and severity masks of the loggers (typically by modifying the setup of the pn_default_logger at startup).

      So, for example, we find in file memory.c:
        if (PN_SHOULD_LOG(logger, PN_SUBSYSTEM_MEMORY, PN_LEVEL_DEBUG)) {
          pn_logger_logf(logger, PN_SUBSYSTEM_MEMORY, PN_LEVEL_DEBUG, "Memory allocation stats:");
          ...
      and the macro PN_SHOULD_LOG will verify (fast) that the call to pn_logger_logf is to be done, when trace is really desired.

      But we have calls that do not have this 'if', e.g. in messenger.c, we have:
        case PN_CONNECTION_INIT:
          pn_logf("connection created: %p", (void *) pn_event_connection(event));
          break;

      where pn_logf is a macro:
        #define pn_logf(...) \
          do

      { \            if (pni_log_enabled()) \                pni_logf_impl(__VA_ARGS__); \     }

      while(0)

      where pni_log_enabled will just return a boolean (true if logging was enabled).
      Then pni_logf_impl is called,
      which then calls pni_vlogf_impl,
      which then calls
        pni_logger_vlogf(pn_default_logger(), PN_SUBSYSTEM_ALL, PN_LEVEL_TRACE, fmt, ap);
      which then formats the string and calls
        pni_logger_log(logger, subsystem, severity, pn_string_get(logger->scratch));
      which then unconditionally calls the logger->sink
      (and the default sink of the pn_default_logger unconditionally writes the msg.

      It looks to us that the call to pni_log_enabled() in pn_logf should in fact be something like:
          if (PN_SHOULD_LOG(logger, PN_SUBSYSTEM_ALL, PN_LEVEL_TRACE)) { \
            pni_logf_impl(_VA_ARGS_); \

      so as to have a consistent logging control.

      Currently, it looks like the logging done via pn_logf is using an alternate mechanism than the central mechanism.
      As far as we can see, only messenger.c contains such pn_logf "unprotected" calls ...

      So messenger.c should likely be converted to the new way to log things.

       

      Extra logging issues, all in messenger.c:

      Some calls to pn_logf are done when the level should be error, but as pn_logf is called, the severity is hardcoded to TRACE.  See pn_error_report in messenger.c

      Most of the errors are not traced, they are just stored in the messenger.  One could have expected that when logging of ERROR level is asked, that any error would be logged.

       

      Attachments

        Activity

          People

            Unassigned Unassigned
            DirkC Dirk Craeynest
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

              Created:
              Updated: