Replace print by the Python logging framework (RFC)

[vdbergh]

Log messages with level >= ERROR give an event log message.

Also: move scheduler to a separate file scheduler.py.

[ppigazzini]

If I'm not wrong you are using the root logger, the best practice is to log at the module level, see at example
https://betterstack.com/community/guides/logging/python/python-logging-best-practices/

class ActionDb:
    def __init__(self, db):
        self.db = db
        self.actions = self.db["actions"]
        self.logger = logging.getLogger(__name__)

[vdbergh]

I am not using the root logger but a child logger with name "fishtest". I am not using __name__ since I am using the same logger everwhere.

I had quite a bit of trouble with this PR since the tutorials did not work. The reason seems to be that pserve already does some configuration. Switching to a child logger fixed things.

EDIT: The reason I am using the same logger everywhere is that loggers seem to require some configuration and I do not want to repeat this.

[ppigazzini]

Pyramid example logs at module level, https://docs.pylonsproject.org/projects/pyramid/en/latest/narr/logging.html

The logger configuration in Pyramid is in the usual ini files:

fishtest/server/production.ini

Lines 37 to 67 in 322eea2

	###
	# logging configuration
	# http://docs.pylonsproject.org/projects/pyramid/en/latest/narr/logging.html
	###
	[loggers]
	keys = root, fishtest
	[handlers]
	keys = console
	[formatters]
	keys = generic
	[logger_root]
	level = ERROR
	handlers = console
	[logger_fishtest]
	level = WARN
	handlers =
	qualname = fishtest
	[handler_console]
	class = StreamHandler
	args = (sys.stderr,)
	level = NOTSET
	formatter = generic
	[formatter_generic]
	format = %(asctime)s %(levelname)-5.5s [%(name)s][%(threadName)s] %(message)s

fishtest/server/development.ini

Lines 32 to 62 in 322eea2

	###
	# logging configuration
	# http://docs.pylonsproject.org/projects/pyramid/en/latest/narr/logging.html
	###
	[loggers]
	keys = root, fishtest
	[handlers]
	keys = console
	[formatters]
	keys = generic
	[logger_root]
	level = INFO
	handlers = console
	[logger_fishtest]
	level = DEBUG
	handlers =
	qualname = fishtest
	[handler_console]
	class = StreamHandler
	args = (sys.stderr,)
	level = NOTSET
	formatter = generic
	[formatter_generic]
	format = %(asctime)s %(levelname)-5.5s [%(name)s][%(threadName)s] %(message)s

[vdbergh]

Hmm that's nice! It seems pyramid already does some of the heavy lifting.

It is not clear to me however how one declares a project specific handler. I am using a handler that posts to the event log.

[vdbergh]

https://stackoverflow.com/questions/30301824/add-custom-log-handler-to-pyramid

[vdbergh]

@ppigazzini The default logging configuration precedes every line with a time stamp. But your logs already seem to have timestamps (provide by systemd?). So I assume you don't want timestamps in the pyramid logs. Is this correct?

[ppigazzini]

Systemd already add the time stamp.

[vdbergh]

Another problem is that currently the constructor for EventHandler takes rundb.actiondb as argument (which itself is constructed inside rundb.init(). It is not obvious to me how handle this without resorting to global variables.

I guess the EvenHandler will have to open a new connection to the db in the constructor. Not a big deal.

[ppigazzini]

If the best practice is to log at module level, log is a global variable that somewhat replace the print function:

def foo():
    message = "Error!"
    print(message)

import logging
log = logging.getLogger(__name__)

def bar():
    message = "Error!"
    log.debug(message)

[vdbergh]

The main motivation for this PR is that I want to define a custom logger that also logs to the event log for level >= ERROR. To replace the pattern

message="error"
print(message, flush=True)
self.actiondb.log_message(fishtest.system, message)

by

message="error"
logger.error(message)

Unfortunately I don't know how to do define a custom handler in the Pyramid framework that takes argument (I tried the last two hours or so but there are errors I don't understand).

[vdbergh]

I think I am getting it to work now.

[vdbergh]

Closing in favor of #2067

[vdbergh]

This 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,
        )