glinscott
Replace print by the Python logging framework
We use the logger "fishtest" as configured in production.ini.
For messages to the event log we use the child logger "fishtest.event", also configured in production.ini.
Log messages are formatted as follows:
INFO [fishtest] [waitress-0:rundb.py:failed_task:1446] <...message...>
Also: move scheduler to a separate file scheduler.py.
This is the code for the custom handler...
class EventHandler(logging.Handler):
def __init__(self):
super().__init__(level=logging.ERROR)
logging.disable(level=logging.CRITICAL)
rundb = RunDb(is_primary_instance=False)
logging.disable(level=logging.NOTSET)
self.actiondb = rundb.actiondb
def emit(self, record):
message=self.format(record)
self.actiondb.log_message(
username="fishtest.system",
message=message,
)
The logging section of production.ini
[loggers]
keys = root, fishtest
[handlers]
keys = console, events
[formatters]
keys = generic
[logger_root]
level = DEBUG
handlers = console
[logger_fishtest]
level = DEBUG
handlers = events
qualname = fishtest
[handler_console]
class = StreamHandler
args = (sys.stderr,)
level = NOTSET
formatter = generic
[handler_events]
class = fishtest.rundb.EventHandler
formatter = generic
[formatter_generic]
format = %(levelname)-5.5s [%(name)s][%(threadName)s] %(message)s
With DEBUG the systemd log is flooded
[logger_fishtest]
level = INFO
handlers = events
qualname = fishtest
I wonder if this is a simpler way to do the intended action...
class EventHandler(logging.Handler):
def __init__(self):
super().__init__(level=logging.ERROR)
rundb = RunDb(is_primary_instance=False)
self.actiondb = rundb.actiondb
def emit(self, record):
if record.levelno >= self.level: # Check if message level is ERROR or higher
message = self.format(record)
self.actiondb.log_message(
username="fishtest.system",
message=message,
)
I am not sure I understand. The handler is already created with level equal to level.ERROR. I don’t understand the need for a further test in emit().
I am AFK but if you want to raise the log levels from DEBUG to INFO then please do!
I now reverted the root level to ERROR and set the fishtest level to DEBUG so that we can use logger.debug(message) inside Fishtest (for example to instrument code). According to the specs, this is how it should be.
I switched back to using a single main logger (this pattern is also used by other packages). The main logger is the logger fishtest which is a child of the root logger which is preconfigured in production.ini. Using a different child logger of fishtest per source file did not seem to offer any benefits and moreover it complicates some things as we are also using a logger which logs to the event log. In this PR this logger is called fishtest.event. With module level logging it should be called __name__.event but then AFAICS it is no longer possible to configure it in production.ini (wildcards in keys appear not to work).
@ppigazzini Could you maybe have a look at this PR? It seems like a nobrainer (replacing print by logger.info) and tying into the Python logger framework has many benefits for interoperability (I plan to do the same for the worker).
But the real reason I am mentioning this is the following: I would like to do some work on the scheduler. This PR moves the scheduler to a separate file scheduler.py. That makes this PR difficult to rebase when there are changes to the scheduler in master as they have to be copied manually to the new file which is very error prone.
I'm working in stealth mode in this weekend: trying new nginx/systemd settings, instrumenting on the fly the code, documenting in the setup script the new setting successfully tested.