Log messages don't show their origin

[Ayuto]

I never really noticed that before, but Source.Python's log messages aren't showing their origin.

Example log message:

2017-07-04 20:35:55 - sp	-	DEBUG	OnEntityDeleted.__init__<<function _on_entity_deleted at 0x1CD16228>>

It's sent by listeners_logger, so the log message should actually say the following:

2017-07-04 20:35:55 - sp.listeners	-	DEBUG	OnEntityDeleted.__init__<<function _on_entity_deleted at 0x1CD16228>>

[jordanbriere]

This is because every _LogInstance internally log to the main _sp_logger:

        # Print to the main SP log file?
        if SP_LOG & areas:

            # Print to the SP log file
            _sp_logger.logger.log(level, msg, *args, **kwargs)

So while formatting the name is sp and not sp.<child>. A lazy fix would be to simply overwrite/restore the logger's name:

        # Print to the main SP log file?
        if SP_LOG & areas:

            # Save/Overwrite the logger's name
            name = _sp_logger.logger.name
            _sp_logger.logger.name = self.logger.name

            # Print to the SP log file
            _sp_logger.logger.log(level, msg, *args, **kwarg)

            # Restore the name
            _sp_logger.logger.name = name

Otherwise it would requires duplicate code with a new formatter in order to handle that specific case.

I'm personally fine with that lazy approach, let me know what you guys are thinking and if we are all okay with it I will go ahead and push it.

However, this won't affect messages logged from the c++ side because _sp_logger is hard-coded into our PythonLog functions. We could implement something similar into them that requires us to pass the desired child for example:

PythonLog(4, "memory", "Searching for a cached signature...");

Which would search for the memory child into _sp_logger and redirect the logging to sp.memory logger. I honestly cannot think of any better solution, because findCaller won't returns anything for these calls.

[jordanbriere]

Pushed a new branch with the suggested changes which fixes both Python and C++ sides. Also removes the PythonLog function that was accepting a "method name" because it was redundant.

From my testings, only the messages logged from __init__.py are displayed from sp alone which I believe was the result wanted. Let me know if you are all fine with this implementation.

[jordanbriere]

Looked more into the logging module and found a better way by using the "extra" keyword!

As a side note, I think we should remove the %Y-%m-%d from the time format, it is redundant since we create a single file per day and we include that info in the file name...

[Ayuto]

Yes, that looks better!

As a side note, I think we should remove the %Y-%m-%d from the time format, it is redundant since we create a single file per day and we include that info in the file name...

Agreed!

[satoon101]

Correct me if I am wrong, but I don't think we create a file each day. I am pretty sure that we create the file at server start using the current day in the file name and continue using that same file no matter which day it is until the server is restarted.

[jordanbriere]

Hmm, good point. If the server is not restarted/SP reloaded daily it should continue with the same file making sense to keep the date logged.

[Ayuto]

Unless we change this behavior as well.

[jordanbriere]

I could certainly see the benefit for servers that stay up for a long period of time.

[jordanbriere]

Also quite easy to implement, using logging.handlers.TimedRotatingFileHandler. For example, replacing line 377 with the following:

            self._handler = TimedRotatingFileHandler(log_path, 'D', 1, 7)

Would automatically rotate to a new file every single day keeping up to a week of logging (oldest files are deleted when rotating to a new one). Tested it with M to create a new one every minute and it worked fine. Not sure I like the <name>.log<date/time> format of the filenames but I could live with that.

[Ayuto]

In an older project I have implemented my own file handler to adress this issue with the file extension:

class RotatingFileHandler(logging.FileHandler):

    """A file handler that writes everything to a day specific file."""

    def __init__(self, filename, mode='a', encoding=None, delay=0,
            strftime='%Y-%m-%d', file_ending='log'):
        self.strftime = strftime
        self.file_ending = file_ending
        super(RotatingFileHandler, self).__init__(
            filename, mode, encoding, delay)

    def _open(self):
        old_filename = self.baseFilename
        self.baseFilename = '%s_%s.%s'% (
            self.baseFilename, time.strftime(self.strftime), self.file_ending)
        stream = super(RotatingFileHandler, self)._open()
        self.baseFilename = old_filename
        return stream

    def emit(self, record):
        self.stream = None
        super(RotatingFileHandler, self).emit(record)

[jordanbriere]

Yeah I'm not sure I like this implementation and would rather use the class shipped with the package. Otherwise we ends up with the same lazy save/restore workaround on the file name. Also, while I'm not too fan of the file extension, it allows the cleanup of the old files which I think is a great feature because who cares of last week or last month logs? Tho the cleanup could also be implemented internally using that format.

I think the right implementation would be something like the following:

class DailyRotatingFileHandler(TimedRotatingFileHandler):
    file_name_format = 'source-python.%Y-%m-%d.log'

    def rotation_filename(self, default_name):
        return date.today().strftime(self.file_name_format)

    def getFilesToDelete(self):
        return_value = list()
        for file_ in LOG_PATH.files():
            try:
                delta = date.today() - datetime.strptime(
                    file_.name, self.file_name_format).date()
                if delta.days < self.backupCount:
                    continue
                return_value.append(file_)
            except ValueError:
                continue
        return return_value

[Ayuto]

I just saw your edit. If your DailyRotatingFileHandler is working fine, it would be great if you could add it. Though, you might can also get rid of the use of LOG_PATH and use the path that is passed to the handler instead.

[jordanbriere]

I've been working/brainstorming on updating the loggers package completely because it currently offer little to no flexibility. The idea would be to inherit from Manager/Logger directly and fully give control over filtering and formatting (#208) to all handlers either it is for us internally or for users that might use the API into their plugins. That way we can offer our own handlers (main log, console and SP log files) by default to all managers while also allowing them to add/remove their owns with the possibility to manipulate the records before emitting to the handlers and that via object-oriented wrappers instead of the current dict-in-a-dict implementation.

I have some drafts of code but didn't have time to put all the pieces together as of yet. Once I'm done with that, I will push to a branch so we can all discuss the implementation.