A problem with DBS logger

[vkuznet]

I found that DBS logger is never issue the messages. Turns out it is related to a bug in WMCore which I fixed in this PR9550.

Here is what happened. The DBSWriterModel class has the following inheritance chain:

DBSWriterModel
   | -> DBSReaderModel
           |-> RESTApi (from WMCore/WebTools/RESTApi .py)
                  |-> WebApi (from WMCore/WebTools/WebApi.py)
                         |-> DatabasePage (from WMCore/WebTools/DatabasePage.py)
                                |-> TemplatedPage (from WMCore/WebTools/Page.py)
                                |-> DBFormatter (from WMCore/Database/DBFormatter.py)

Now, the Page class defines log,info,warning,exception,debug methods which calls cplog.error_log.log. While self.logger is defined in DBFormatter class. The problem was that DBFormatter class was improperly initialized from DatabasePage one. As shown in PR9550 instead of using logger it passed self and self.logger was assigned to self itself. Because self object (e.g. DBWriterModel) had log,info,warning,exception,debug methods from Page class no issues were seen, but no logging message either since logging was redirected to cplog.

With PR9550 fix now all DBS classes will yield messages in a logger defined in DBFormatter if self.logger.xxx call will be used. But in order to know where messages comes from DBS self.logger should define proper name, e.g. in DBSGlobalWriter we need to have self.logger.name = __name__ assignment. I'll make an additional PR for that.

[yuyiguo]

@vkuznet I understood your analysis here, it was an ugly code how WMcore handle logging. But we all knew that WMCore use cherrypy logger instead of python logging. DBS have been logged all its messages all the time. I don't get how you get the logging problem?

[vkuznet]

For starter, the current code yield all messages under

<LEVEL>:cherrypy.error

where LEVEL correspond to level of the logger, therefore if error occurred in DBSReader or DBSWriter, or WMCore, it will have identical prefix which is hard to understand where it comes from.

Then, there is no easy way to change logging level for entire codebase, e.g. the Page class has these methods:

class Page(WMObject):
    def warning(self, msg=None):
        self.log(msg, logging.WARNING)
    def exception(self, msg=None):
        self.log(msg, logging.ERROR)

    def error(self, msg=None):
        self.log(msg, logging.ERROR)

    def debug(self, msg=None):
        self.log(msg, logging.DEBUG)

    def info(self, msg=None):
        self.log(msg, logging.INFO)

    def log(self, msg=None, severity=logging.INFO):
        if not isinstance(msg, str):
            msg = str(msg)
        if msg:
            cplog.error_log.log(severity, msg)

which implies that even I setup cplog to certain level of logging its level will be ignored in those methods since they accept logging level and not the one I may setup for entire application. As such we can't properly configure the application with proper logging level.

For instance, the entire puzzle started from this line https://github.com/dmwm/DBS/blob/master/Server/Python/src/dbs/web/DBSWriterModel.py#L53 which NEVER prints the message. Then I realized that my calls to self.logger.warning may not be printed as well due to aforementioned issue. Then I realized that I can't change logger of DBS classes from external config because it boils down to cplog settings.

Because of deep inheritance chain I don't even know which logger is used in DBS and therefore can't control it. As in my original PR I just used print statement and they were fine, but now with logger everything is a mystery and I have no idea which logging parts of DBS is actually working appropriately.

You can easily verify that https://github.com/dmwm/DBS/blob/master/Server/Python/src/dbs/web/DBSWriterModel.py#L53 is never printed in DBS logs, and I don't know if self.logger.warning part will be printed as well.

[vkuznet]

So to illustrate, I put these statement in DBSGlobalWriter:

        self.logger.name = __name__
        self.logger.info("INFO call")
        self.logger.debug("DEBUG call")
        self.logger.warning("WARNING call")
        self.logger.exception("Exception call")
        self.logger.error("error call")

and I got the following output:

WARNING:cherrypy.error:WARNING call
ERROR:cherrypy.error:Exception call
ERROR:cherrypy.error:error call

Neither info or debug messages were printed out. There is no information where these messages comes from, i.e. as I wrote if message comes from DBSReader or DBSWriter or DBS business logic there is no way to know were it originated (unless the message itself does contain the origin). The exception is not an Error, while the prefixes for them are identical (again the only way to distinguish would be rely on message itself).

It is up to you to decide how to deal with logging, but to me it is totally broken, and event it prints exceptions and errors, it may be very tedious to identify where the messages comes from unless someone will match message pattern with a codebase.

I proposed to fix the issue, first it should be fixed in WMCore (https://github.com/dmwm/WMCore/pull/9550) and then if you apply https://github.com/dmwm/DBS/pull/630 you'll have proper prefix for messages based on a class name (more classes may be patched as well).

[yuyiguo]

Yes, we had to encode the origin in the error message. We had debug message worked in the past if I recalled correctly. We could not control the level of the logging so we had to comment out the debug code.

[yuyiguo]

@vkuznet I merged #630. I just want to double check with you that this fixing will move all the loggers out of cherrypy logger and use python logger instead.

[vkuznet]

Yuyi, the migration from cherrypy to python logger is due to this PR https://github.com/dmwm/WMCore/pull/9550, while #630 only fixes the logger names. Basically you need both to make a switch from cherrypy to python logger.

[yuyiguo]

Yes both PRs work together. It is great to move away from cp logger.