logging in a file give a blank file

[chechigp]

I tested the examples from library and always get an empty file. I posted the problem in discord and also other user get the same result.

Using the example_logging_1.py with the below basic modification to write a file or the example_logging_2.py with handlers the result is always a blank file.

import lib.logging.logging as logging

logging.basicConfig(level=logging.INFO, filename="basictest.txt")
log = logging.getLogger("test")
log.debug("Test message: %d(%s)", 100, "foobar")
log.info("Test message2: %d(%s)", 100, "foobar")
log.warning("Test message3: %d(%s)")
log.error("Test message4")
log.critical("Test message5")
logging.info("Test message6")

try:
    1 / 0
except:
    log.exception("Some trouble (%s)", "expected")

class MyHandler(logging.Handler):
    def emit(self, record):
        print("levelname=%(levelname)s name=%(name)s message=%(message)s" % record.__dict__)

logging.getLogger().addHandler(MyHandler())
logging.info("Test message7")

I'm using logger 0.5, and an ESP32 with micropython 1.19.1 or 1.20.0.

Thanks in advance

[jimmo]

This works for me on unix, pybd, and esp32.

e.g. on esp32:

$ mpr mip install logging
Install logging
Installing logging (latest) from https://micropython.org/pi/v2 to /lib
Installing: /lib/logging.mpy
Done                                        
$ mpr ls
ls :
         139 boot.py
           0 lib/
$ mpr run example_logging_2.py 
None.000 - __main__ - DEBUG - debug message
None.000 - __main__ - INFO - info message
None.000 - __main__ - WARNING - warn message
None.000 - __main__ - ERROR - error message
None.000 - __main__ - CRITICAL - critical message
None.000 - __main__ - INFO - message arg 5
None.000 - __main__ - INFO - message 1 20
None.000 - __main__ - ERROR - Some trouble (expected)
$ mpr ls
ls :
         139 boot.py
         148 error.log
           0 lib/
$ mpr cat error.log
None.000 - __main__ - ERROR - error message
None.000 - __main__ - CRITICAL - critical message
None.000 - __main__ - ERROR - Some trouble (expected)
$ mpr run issue_664.py 
levelname=INFO name=root message=Test message7
$ mpr ls
ls :
         208 basictest.txt
         139 boot.py
         148 error.log
           0 lib/
$ mpr cat basictest.txt
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)
INFO:root:Test message7

(mpr is my local alias for mpremote)

Maybe could you confirm that you have the correct logging.py (i'm curious as to the import line -- import lib.logging.logging as logging, this means you must have installed it manually?) Can you share the exact contents of /lib/logging/logging.py ?

[chechigp]

Thanks jimmo for your time testing it.

Well, it works also for my when I imported it using mip in micropython 1.20.0. And yes, I installed it manually and the file I'm using is: https://github.com/micropython/micropython-lib/blob/master/python-stdlib/logging/logging.py That I supposed is the last one. :S

Any idea why it seems to fail the logging.py from the git but not the precompiled mpy from mip?

Thanks again for your time

[jimmo]

Any idea why it seems to fail the logging.py from the git but not the precompiled mpy from mip?

They should be exactly the same file. You could add the --no-mpy flag to mip (which will give you the .py instead of the .mpy file) and verify it has the same contents.

It also works for me if I copy logging.py directly.

The way this is supposed to work is that the FileHandler never gets a chance to close the file (i.e. it's close method is never called), but the open file is automatically closed by the soft reset. mpremote triggers a soft reset on connection, so when I run the subsequent mpr ls the file will have been flushed.

So for example, if I run the script above, but then hard reset the board, then I will see the empty file.

Or, if I tell mpr not to trigger a soft reset using the resume command.

$ mpr ls
ls :
         139 boot.py
           0 lib/
$ mpr run issue_664.py 
levelname=INFO name=root message=Test message7
$ mpr resume ls  # ls in the same context as the script ran (close won't have been called)
ls :
           0 basictest.txt
         139 boot.py
           0 lib/
$ mpr ls  # soft reset then ls
ls :
         208 basictest.txt
         139 boot.py
           0 lib/

You can see the file didn't have any contents until the soft reset.

So either:

1. Your log handler is never actually getting written to. You could confirm this by adding print statements to StreamHandler.emit.
2. Cleanup is never happening before you're trying to look at the log files (i.e. no soft reset).
3. Something is wrong with running finalisers on open file objects.

You can debug (1) by adding print statements to StreamHandler.emit in logging.py (2) is just how this is supposed to work. logging.py never explicitly flushes the files (because it takes time and wears the flash unnecessarily) but you can explicitly use file_handler.stream.flush() if you want that. (But you shouldn't need to do this) And you could verify (3) at the REPL by doing:

>>> f = open("foo.txt", "w")
>>> f.write("hello")
5
>>> # Hit Ctrl-D here
MPY: soft reboot
MicroPython v1.20.0 on 2023-04-26; TinyPICO with ESP32-PICO-D4
Type "help()" for more information.
>>> f = open("foo.txt", "r")
>>> f.read()
'hello'

[jimmo]

the result is always a blank file.

@chechigp Can you confirm how you're accessing the file? Were you using something other than mpremote initially, but then started using mpremote to use mip and that's why it's working now?

Other tools (Thonny, ampy, rshell, etc?) might not be doing an automatic soft reset.

[chechigp]

the result is always a blank file.

@chechigp Can you confirm how you're accessing the file? Were you using something other than mpremote initially, but then started using mpremote to use mip and that's why it's working now?

Other tools (Thonny, ampy, rshell, etc?) might not be doing an automatic soft reset.

My apologies for the late reply. Yes I use Thonny and when you stop the script Thonny do not make a soft reset and therefore the file is not saved. The strange behavior is when I used the precompiled module from mip, then the file is saved with the spot button. Anyway all seems to be clear, finally I made a function to call to save the file every X minutes and work well. Thanks for your time! I close the issue.