logging: Improve the logging module.

[iabdalkader]

• Add support for all format specifiers, support for datefmt using strftime, and support for Stream and File handlers.
• Ports/boards that need to use FileHandlers should enable MICROPY_PY_SYS_ATEXIT, and enabled MICROPY_PY_SYS_EXC_INFO if using logging.exception().

[andrewleech]

Thanks for this, a cleanup of the logging module has been on my shortlist of todo so I'm quite interested.

On an initial quick skim through the changelog this looks like a good broad cleanup, with sensible additions added without too much extra "code bulk".

I've had a couple of early planning discussions with colleagues about this module and they always end up swinging back and forth between which features will be good for most users, but also small enough to fit on most ports/boards.

At first glance I feel there's a pretty good balance here! the included handlers are fairly simple, but should also provide a good base (and example) to be extended upon by individual users to meet their project. I'm also inclined to think that more complex handlers (eg. size limited and timestamped rotating files) could happily go in separate packages.

I'm keen to review and test in more depth in then coming days (hopefully) but in the mean time, can you confirm whether the included classes confirm to (a sunset of) the cpython logging module? By memory they look good, but just want to check.

[iabdalkader]

Yes, this conforms to CPython logging (I've implemented it following the docs), both the API and functionality are compatible (if you run it on CPython you get the exact same output in stream/file).

think that more complex handlers (eg. size limited and timestamped rotating files) could happily go in separate packages

That's a good idea, more handlers can be added in a separate module and imported in __init__.py something like this:

try
 from logging_handlers import *
except:
   pass

[iabdalkader]

Updated.

[iabdalkader]

Does this run every time logging is imported ?

if hasattr(sys, "atexit"):
    sys.atexit(shutdown)

[dpgeorge]

Does this run every time logging is imported ?

No, a module is only ever executed once, the first time it is imported. So that atexit register will run only once.

[iabdalkader]

No, a module is only ever executed once, the first time it is imported. So that atexit register will run only once.

Yeah just wanted to double check. I think it's ready now, unless there's something else ?

Would be nice if this is available too with the updated logging: https://github.com/micropython/micropython-lib/pull/508

[stinos]

While at it could you perhaps add

def addLevelName(level, name):
    _level_dict[level] = name

and

def log(level, msg, *args):
    getLogger().log(level, msg, *args)

? I'm using these for CPython compatibility.

[dpgeorge]

Testing this, I see that the basic use where you just start logging doesn't work (at least it doesn't match CPython). Eg:

import logging
logging.warning('test')

The above use-case should match CPython (ie the default logger should print out with the default formatting).

[ThinkTransit]

If handlers are being added can a RotatingFileHandler be considered?

Ported from cpython

class RotatingFileHandler(Handler):
    def __init__(self, filename, maxsize=128_000, backupCount=5):
        if maxsize < 256:
            raise ValueError("maxsize must be at least 256 B")
        self.filename = filename
        self.maxsize = maxsize
        self.backupCount = backupCount
        self.formatter = Formatter()

        try:
            # checks if file exists and prevents overwriting it
            self.pos = os.stat(self.filename)[6]
            self.file = open(filename, "r+")
        except OSError:
            self.pos = 0
            self.file = open(filename, "w+")

        self.file.seek(self.pos)

    def shouldRollover(self, record):
        """
        Determine if rollover should occur.
        Basically, see if the supplied record would cause the file to exceed
        the size limit we have.
        """
        message = self.format(record)
        if len(message) + self.pos > self.maxsize:
            return True
        else:
            return False


    def doRollover(self):
        """
        Do a rollover.
        """
        # Close current file first
        self.file.close()

        if self.backupCount > 0:
            for i in range(self.backupCount - 1, 0, -1):
                sfn = "%s.%d" % (self.filename, i)
                dfn = "%s.%d" % (self.filename, i + 1)
                try:
                    os.rename(sfn, dfn)
                except:
                    print(f"Cant move file {sfn} to {dfn}")

            dfn = self.filename + ".1"
            try:
                os.rename(self.filename, dfn)
            except:
                print(f"Couldnt move file {self.filename} to {dfn}")

        print("Rollover complete")
        self.pos = 0
        self.file = open(self.filename, "w+")
        self.file.seek(self.pos)

[iabdalkader]

basic use where you just start logging doesn't work

@dpgeorge Fixed, thanks.

While at it could you perhaps add

@stinos Added.

If handlers are being added can a RotatingFileHandler be considered?

@ThinkTransit Handlers will be added, just not in this PR, and probably in a separate package.

[iabdalkader]

Just a minor optimization, this will only init the root logger and only if it's not initialized.

def getLogger(name="root"):
    if name not in loggers:
        loggers[name] = Logger(name)
        if name == "root":
            basicConfig()
    return loggers[name]

So basic example will init root logger:

import logging
logging.warning('test')

Creating a logger wont:

logging.getLogger(__name__)

[iabdalkader]

ping @dpgeorge

[dpgeorge]

Creating a logger wont

So this means the following code (with this PR as it currently is) won't print anything:

>>> import logging
>>> logging.getLogger('log').warning('test')

Whereas the code before this PR did print a message, and CPython does as well. I think it should work like it did before (and hence be CPython compatible).

[iabdalkader]

I think it should work like it did before (and hence be CPython compatible).

It was Not CPython compatible because it printed a logger name, level etc.. where as CPython would just print the message, but now it is. There's no global _level though, but feel free to add it if you want.

Pushed an update to fix the other comments.

[iabdalkader]

Would it be better if https://github.com/micropython/micropython-lib/pull/508 is included in logging ?

[dpgeorge]

Would it be better if #508 is included in logging ?

Yes that might be a good short-term solution, to include it here as a private function, eg _strftime. Then at least that unblocks this PR and makes it "just work". We can improve/factor things later on.

[iabdalkader]

to include it here as a private function, eg _strftime

I prefer to keep strftime in its own file, just more readable and easier to remove later. So if you look at the updated PR now, it checks if time has strftime, if not it will import the included strftime. This allows the other PR to be merged without breaking this.

[dpgeorge]

So if you look at the updated PR now, it checks if time has strftime, if not it will import the included strftime

I'm not sure this will work as expected because strftime.py will not be installed by mip, because it's not listed in manifest.py. Probably you can specify multiple module() entries in manifest.py, but that's a bit of a hack. Would be cleaner to just include strftime in logging.py (and that still allows the other PR to be merged, it'll just continue to use the local one).

[iabdalkader]

I'm not sure this will work as expected because strftime.py will not be installed by mip, because it's not listed in manifest.py.

I see, well in that case I think the cleanest option would be to revert to the old package structure, add that in the manifest ? i.e:

logging/__init__.py
logging/logging.py
logging/strftime.py

Would also be nice if examples are put in an examples/ dir, to match some of the other packages.

[dpgeorge]

Maybe it's better if we merge #508... I'll will look into that.

Would also be nice if examples are put in an examples/ dir, to match some of the other packages.

Yes, that can be done here, even if the module itself stays simply as logging.py (ie no package structure).

[iabdalkader]

Alright, removed strftime.py, moved examples to examples/ (I added the basic test case you mentioned), reverted the change in logging.py (it will print None if there's no strftime).

Maybe it's better if we merge https://github.com/micropython/micropython-lib/pull/508... I'll will look into that.

Yes please do, log time is very important.

[dpgeorge]

This is getting better, however it still doesn't match the existing behaviour of this module or CPython for the existing example.

The existing example with the existing library had this output:

INFO:test:Test message2: 100(foobar)
WARN:test:Test message3: %d(%s)
ERROR:test:Test message4
CRIT:test:Test message5
INFO:root:Test message6
ERROR:test:Some trouble (expected)
Traceback (most recent call last):
  File "x.py", line 13, in <module>
ZeroDivisionError: divide by zero
levelname=INFO name=root message=Test message7

Which is quite close to CPython's output run against that same example.

With the new library here, that example has the output:

Test message: %d(%s)
Test message2: %d(%s)
Test message3: %d(%s)
Test message4
Test message5
Some trouble (%s)

@iabdalkader please can you add back the existing example as a separate example file in the examples directory, and then make it so the new library run on that example gives similar output to before (which should be similar or very close to the output CPython gives on that example).

[iabdalkader]

please can you add back the existing example as a separate example

@dpgeorge I did, it's in examples/example_logging_1.py and I found some issues and fixed them. The log should be identical to CPython now (with the exception of the longer backtrace exception from CPython):

$ mpremote mount . run examples/example_logging_1.py
Local directory . is mounted at /remote
INFO:test:Test message2: 100(foobar)
WARNING:test:Test message3: %d(%s)
ERROR:test:Test message4
CRITICAL:test:Test message5
INFO:root:Test message6
ERROR:test:Some trouble (expected)
Traceback (most recent call last):
  File "<stdin>", line 13, in <module>
ZeroDivisionError: divide by zero
INFO:root:Test message7
levelname=INFO name=root message=Test message7

The existing example with the existing library had this output:

Note I'm aiming for max compatibility with CPython Not with the old logging library (which is missing basic things like logging.warning), so I can't use the old library for reference, for example the old library doesn't print "message7" CPython prints it and so does the updated module.

[stinos]

Regarding CPython-compatibility: I only now ran this implementation against a bunch of code I have and it seems there are some things which might be worth making compatible since it's new code anyway. Sorry I'm somewhat late with this, and I probably didn't check everything, but here are some things I ran into:

• default argument for getLogger in CPython is None (which means 'get root logger'), but in this implementation getLogger(None) returns a Logger with name None instead of 'root'.
• same for basicConfig and Formatter and StreamHandler and so on, which mostly have None as default arguments (this one I didn't actually run into, but is also simpler to implement anyway: for example instead of repeating fmt=_default_fmt in a couple of places, you just use fmt=None everywhere to indicate you want the default format, and then there's only one single place, Formatter.__init__, where this gets interpreted as _default_fmt).
• not officially documented but the default format in CPYthon is logging.BASIC_FORMAT and other implementations use that as well. So since we're adding constants anyway, why not use the same name?
• Logger.__init__ has level as last argument
• the basicConfig implementation doesn't do the same as CPython's. Didn't figure out what exactly but from the looks of it, force=True does not remove all handlers it just closes them, plus level and format are only applied to the new handler created instead of to all existing handlers.

[iabdalkader]

default argument for getLogger in CPython is None Logger.init has level as last argument force=True does not remove all handlers it just closes them same for basicConfig and Formatter and StreamHandler and so on, which mostly have None as default arguments

The above should be fixed now.

the default format in CPYthon is logging.BASIC_FORMAT and

Not changing this because we'll then prefix it with an underscore, and it will be different anyway so I don't see the point.

Note I'm reluctant to change anything else in this PR, unless it's a bug, I don't want to risk breaking something else which will result in another review/fix cycle, and I really need a usable logging in micropython-lib as soon as possible.

[dpgeorge]

Note I'm reluctant to change anything else in this PR, unless it's a bug

Yes I agree, it would be good to finalise on this PR, and anything else can be an extension done as a follow up.

[stinos]

I understand, but in my opinion the very basics should at least work.

import logging
import sys

root = logging.getLogger('root')
logging.basicConfig(level=logging.DEBUG, stream=sys.stdout)
logging.info('hello upy')
logging.shutdown()

part deleted, didn't test with last version

So I really think the minimal basicConfig implementation should at least be somewhat sound.

[iabdalkader]

So I really think the minimal basicConfig implementation should at least be somewhat sound.

When you first call getLogger("root") it sets up the root logger using the default log level WARNING (same default level in CPython), the following call to basicConfig() without force=True is ignored, as it should be according to the docs:

This function does nothing if the root logger already has handlers configured, unless the keyword argument force is set to True.

So logging.info(), which is lower than warning, shouldn't print anything, as expected, can you explain why it should be otherwise ?

Running your example on CPython does print something, not sure why, and more interesting if you change it to the following, it doesn't print anything.

root = logging.getLogger('root')
logging.info('hello upy')
logging.basicConfig(level=logging.DEBUG)
logging.info('hello upy')

part deleted, didn't test with last version

I think I forgot to push after the latest changes, using None etc... but it's updated now.

EDIT: Maybe by default CPython doesn't add any handlers to the root longer, in that case the above would print the log.

[stinos]

can you explain why it should be otherwise

Only because I ran it in CPython and it printed output :) But actually the code isn't a real usecase, I only started typing it because I wanted to show that the previous version which didn't clear all handlers was an issue.

But with that fixed it's ok as far as I'm concerned.

By default CPython doesn't add any handlers to the root longer

It does but only upon the first logging statement issued. But I don't think that matters.

What might matter though: in CPython logging.getLogger(None) is the one and only root logger, which is the parent of all other loggers, and hence which is not the the same as getLogger('root') (it is the same as logging.root though but that's an implementation detail). So configuring formatting globally on the root logger (which I think is rather common, and in any case it seems to make sense to me - with some bias becuase I do have multiple projects doing this) like:

logging.basicConfig(level=logging.DEBUG, stream=sys.stdout)
for handler in logging.getLogger().handlers:
    handler.setFormatter(logging.Formatter("[%(levelname)s]:%(name)s:%(message)s"))
logging.info('hello upy')
logging.getLogger('child').info('hello 2')

outputs

[INFO]:root:hello upy
[INFO]:child:hello 2

in CPython but

[INFO]:root:hello upy
INFO:child:hello 2

in MicroPython, and that last line only appears because there's a print statement in Logger, it doesn't do propagation like CPython does. However since that was already the case before this shouldn't be changed in this PR.

[iabdalkader]

there's a print statement in Logger, it doesn't do propagation like CPython does. However since that was already the case before this shouldn't be changed in this PR.

That's an interesting example that shows a shortcoming of both the old and new logger, yes the print statement outputs the second line instead of propagating the log to the higher loggers (and to the root logger which prints that second line on CPython). And this was indeed the old behavior which Damien wanted to maintain, but it also seemed to me like the hierarchy would be an overkill for MicroPython. Maybe a middle ground solution would be to call the root logger instead print ? Something like:

def log(self, level, msg, *args):
    if self.isEnabledFor(level):
        if args:
            if isinstance(args[0], dict):
                args = args[0]
            msg = msg % args
        self.record.set(self.name, level, msg)
        handlers = self.handlers
        if not handlers:
            handlers = getLogger().handlers
        for h in handlers:
            h.emit(self.record)

With the above now your example outputs:

mpremote mount . run test2.py 
Local directory . is mounted at /remote
[INFO]:root:hello upy
[INFO]:child:hello 2

But with that fixed it's ok as far as I'm concerned.

Yes I can confirm this and everything in my previous comment should be fixed, I just forgot to push the changes sorry about the confusion.