File Logger not working as expected

[CiaranWelsh]

I tried the example in the "Switching to the file logger" section. Nothing is saved to the log file.

pyomexmeta: 1.2.12
python: 3.9.5
OS: Ubuntu

Originally posted by @jonrkarr in #87 (comment)

[jonrkarr]

This can be reproduced with the python:3.9-slim-buster Docker image.

• Ubuntu
• Python 3.9.6
• pyomexmeta 1.2.12

[jonrkarr]

1. Pull and run image

   docker pull python:3.9-slim-buster
   docker run -it --rm --entrypoint bash python:3.9-slim-buster

2. Install pyomexmeta and run python

   pip install pyomexmeta
   python

3. Execute example and print log

   from os.path import join, exists, dirname, abspath
   from os import remove
   from pyomexmeta import RDF, Logger
   
   cellml = '''<?xml version=\"1.1\" encoding=\"UTF-8\"?>
           <model xmlns=\"http://www.cellml.org/cellml/1.1#\" xmlns:cmeta=\"http://www.cellml.org/metadata/1.0#\" xmlns:xlink=\"http://www.w3.org/1999/xlink\" xmlns:rdf=\"http://www.w3.org/1999/02/22-rdf-syntax-ns#\" xmlns:bqs=\"http://www.cellml.org/bqs/1.0#\" xmlns:semsim=\"http://bime.uw.edu/semsim/#\" xmlns:dc=\"http://purl.org/dc/terms/\" xmlns:vCard=\"http://www.w3.org/2001/vcard-rdf/3.0#\" name=\"annotation_examples\" cmeta:id=\"annExamples\">
             <component name=\"main\">
               <variable cmeta:id=\"main.Volume\" initial_value=\"100\" name=\"Volume\" units=\"dimensionless\" />
               <variable cmeta:id=\"main.MembraneVoltage\" initial_value=\"-80\" name=\"MembraneVoltage\" units=\"dimensionless\" />
               <variable cmeta:id=\"main.ReactionRate\" initial_value=\"1\" name=\"ReactionRate\" units=\"dimensionless\" />
             </component>
           </model>'''
   
   logger_file = "log.log"
   print("check logger_file: " , logger_file)
   
   # if already exists, remove
   if exists(logger_file):
       remove(logger_file)
   assert not exists(logger_file)
   
   # activate the file logger
   Logger.file_logger(logger_file)
   rdf = RDF.from_string(cellml, syntax="turtle") # nothing is emitted to console
   
   # now check logger_file
   with open(logger_file, 'r') as file:
         print(file.read())

[CiaranWelsh]

So this is strange because although log.log is created and written to, the Python code for reading the file does not work. I'm using your environment (steps 1 and 2 above).

root@5c5c5da545e7:/# ls
bin  boot  dev  etc  home  lib  lib64  media  mnt  opt  proc  root  run  sbin  srv  sys  tmp  usr  var

Now create a little Python script

# CheckLogger.py

from os.path import join, exists, dirname, abspath
from os import remove
from pyomexmeta import RDF, Logger

cellml = '''<?xml version=\"1.1\" encoding=\"UTF-8\"?>
        <model xmlns=\"http://www.cellml.org/cellml/1.1#\" xmlns:cmeta=\"http://www.cellml.org/metadata/1.0#\" xmlns:xl$          <component name=\"main\">
            <variable cmeta:id=\"main.Volume\" initial_value=\"100\" name=\"Volume\" units=\"dimensionless\" />
            <variable cmeta:id=\"main.MembraneVoltage\" initial_value=\"-80\" name=\"MembraneVoltage\" units=\"dimensio$            <variable cmeta:id=\"main.ReactionRate\" initial_value=\"1\" name=\"ReactionRate\" units=\"dimensionless\" $          </component>
        </model>'''

logger_file = join(dirname(__file__), "log.log")
print("The logger file is here: " , logger_file)

# if already exists, remove
if exists(logger_file):
    remove(logger_file)

# verify the logger file does not exist
assert not exists(logger_file), "The logger file exists"

# activate the file logger
Logger.file_logger(logger_file)
rdf = RDF.from_string(cellml, syntax="turtle") # nothing is emitted to console

# check the logger file exists

assert exists(logger_file), "logger file does not exist"
# now check logger_file
with open(logger_file, 'r') as file:
    print(file.read())

This unexpectedly does not read the log.log file and print to console, but when you do ls

root@5c5c5da545e7:/# ls
CheckLogger.py  boot  etc   lib    *log.log*  mnt  proc  run   srv  tmp  var
bin             dev   home  lib64  media    opt  root  sbin  sys  usr
root@5c5c5da545e7:/#

and nano log.log

[09:52:57 +00:00]  error : syntax error at '<'

[jonrkarr]

Is the log being written to file asynchronously, or when the program closes? Perhaps the log file needs to be flushed to disk?

[CiaranWelsh]

Looks like flush was the solution - thanks for the suggestion. Can you let me know if v1.2.13 resolves this issue? It works for me but I've done this quickly so I can get back to the roadrunner project.

[jonrkarr]

The first error in RDF reading is now saved to a log file. However, subsequent errors are not.
e.g.,

import pyomexmeta

# setup logger

pyomexmeta.RDF.from_file(bad_file)
pyomexmeta.Logger.flush()
# log file is non-empty

pyomexmeta.RDF.from_file(bad_file_2)
pyomexmeta.Logger.flush()
# log file is empty

I have this in a unittest. I'll try to distill this to a minimal example.

[CiaranWelsh]

We don't have the flushing problem in C++ - it seems. We might have the flushing problem in the C layer but I checked Python first, which works as I expected (so I assume C is also okay).

Basically I have behaviour that looks like this (v1.2.13):

    def test_logger_file_flush_none(self):
        print("")
        from os.path import join, exists, dirname, abspath
        from os import remove, getcwd
        from pyomexmeta import RDF, Logger

        logger_file = join(getcwd(), "log.log")
        print("logger file is: ", logger_file)

        # if already exists, remove
        if exists(logger_file):
            remove(logger_file)
        assert not exists(logger_file)

        # activate the file logger
        Logger.file_logger(logger_file)
        Logger.set_formatter("%v") # no fancy stuff
        rdf1 = RDF.from_string(TestStrings.cellml, syntax="turtle")  # nothing is emitted to console
        # Logger.flush()

        rdf2 = RDF.from_string(TestStrings.cellml, syntax="turtle")  # nothing is emitted to console
        # Logger.flush()

        # now check logger_file
        with open(logger_file, 'r') as file:
            # empty without flush
            self.assertTrue(file.read() == "")

output:

============================= test session starts =============================
collecting ... collected 1 item

pyomexmeta_tests.py::LoggerTests::test_logger_file_flush_none PASSED     [100%]
logger file is:  D:\libOmexMeta\tests\python\log.log



============================== 1 passed in 2.11s ==============================

    
    def test_logger_file_flush_1(self):
        print("")
        from os.path import join, exists, dirname, abspath
        from os import remove, getcwd
        from pyomexmeta import RDF, Logger

        logger_file = join(getcwd(), "log.log")
        print("logger file is: ", logger_file)

        # if already exists, remove
        if exists(logger_file):
            remove(logger_file)
        assert not exists(logger_file)

        # activate the file logger
        Logger.file_logger(logger_file)
        rdf1 = RDF.from_string(TestStrings.cellml, syntax="turtle")  # nothing is emitted to console
        Logger.flush()

        rdf2 = RDF.from_string(TestStrings.cellml, syntax="turtle")  # nothing is emitted to console
        # Logger.flush()

        # now check logger_file
        with open(logger_file, 'r') as file:
            print(file.read())

output

============================= test session starts =============================
collecting ... collected 1 item

pyomexmeta_tests.py::LoggerTests::test_logger_file_flush_1 PASSED        [100%]
logger file is:  D:\libOmexMeta\tests\python\log.log
[18:12:28 +01:00]  error : syntax error at '<' 



============================== 1 passed in 1.72s ==============================

    def test_logger_file_flush_2(self):
        print("")
        from os.path import join, exists, dirname, abspath
        from os import remove, getcwd
        from pyomexmeta import RDF, Logger

        logger_file = join(getcwd(), "log.log")
        print("logger file is: ", logger_file)

        # if already exists, remove
        if exists(logger_file):
            remove(logger_file)
        assert not exists(logger_file)

        # activate the file logger
        Logger.file_logger(logger_file)
        rdf1 = RDF.from_string(TestStrings.cellml, syntax="turtle")  # nothing is emitted to console
        Logger.flush()

        rdf2 = RDF.from_string(TestStrings.cellml, syntax="turtle")  # nothing is emitted to console
        Logger.flush()

        # now check logger_file
        with open(logger_file, 'r') as file:
            print(file.read())

output

============================= test session starts =============================
collecting ... collected 1 item

pyomexmeta_tests.py::LoggerTests::test_logger_file_flush_2 PASSED        [100%]
logger file is:  D:\libOmexMeta\tests\python\log.log
[18:12:56 +01:00]  error : syntax error at '<' 
[18:12:56 +01:00]  error : syntax error at '<' 



============================== 1 passed in 1.74s ==============================

    def test_logger_file_flush_at_end(self):
        print("")
        from os.path import join, exists, dirname, abspath
        from os import remove, getcwd
        from pyomexmeta import RDF, Logger

        logger_file = join(getcwd(), "log.log")
        print("logger file is: ", logger_file)

        # if already exists, remove
        if exists(logger_file):
            remove(logger_file)
        assert not exists(logger_file)

        # activate the file logger
        Logger.file_logger(logger_file)
        rdf1 = RDF.from_string(TestStrings.cellml, syntax="turtle")  # nothing is emitted to console

        rdf2 = RDF.from_string(TestStrings.cellml, syntax="turtle")  # nothing is emitted to console
        Logger.flush()

        # now check logger_file
        with open(logger_file, 'r') as file:
            print(file.read())

output:

============================= test session starts =============================
collecting ... collected 1 item

pyomexmeta_tests.py::LoggerTests::test_logger_file_flush_at_end PASSED   [100%]
logger file is:  D:\libOmexMeta\tests\python\log.log
[18:13:24 +01:00]  error : syntax error at '<' 
[18:13:24 +01:00]  error : syntax error at '<' 



============================== 1 passed in 2.29s ==============================

[jonrkarr]

Once I realized you added methods for getting the log data, I switched to using that. That seems to work well.

Here's a minimal example for the file logger issue.

1. Run Docker container

   docker run -it --rm \
       --entrypoint bash \ 
       --mount type=bind,source=/home/jonrkarr/Documents/Biosimulators_utils/tests/fixtures/omex-metadata,target=/root/fixtures \
       python:3.9-slim-buster 

2. Install pyomexmeta and run ipython

   pip install pyomexmeta ipython
   ipython

3. Read an invalid file once (and the log file is non-empty). Read it again (and the log file is empty).

   import os
   import pyomexmeta
   import tempfile
   
   invalid_filename = '/root/fixtures/invalid.rdf'
   
   # read once
   log_file, log_filename = tempfile.mkstemp()
   os.close(log_file)
   os.remove(log_filename)
   pyomexmeta.Logger.file_logger(log_filename)
   
   rdf = pyomexmeta.RDF.from_file(invalid_filename, 'rdfxml')
   
   pyomexmeta.Logger.flush()
   
   assert os.path.isfile(log_filename)
   with open(log_filename, 'r') as file:
       print(file.read())
   
   # read again
   log_file, log_filename = tempfile.mkstemp()
   os.close(log_file)
   os.remove(log_filename)
   pyomexmeta.Logger.file_logger(log_filename)
   
   rdf = pyomexmeta.RDF.from_file(invalid_filename, 'rdfxml')
   
   pyomexmeta.Logger.flush()
   
   assert os.path.isfile(log_filename)
   with open(log_filename, 'r') as file:
       print(file.read())

4. This prints the following to the console, indicating that the second log file wasn't created.

   [18:43:18 +00:00]  error : XML parser error: expected '>' 
   [18:43:18 +00:00]  error : XML parser error: Char 0x0 out of allowed range 
   [18:43:18 +00:00]  error : XML parser error: Char 0x0 out of allowed range 
   [18:43:18 +00:00]  error : XML parser error: expected '>' 
   
   ---------------------------------------------------------------------------
   AssertionError                            Traceback (most recent call last)
   <ipython-input-4-91f56c66bd94> in <module>
        29 pyomexmeta.Logger.flush()
        30 
   ---> 31 assert os.path.isfile(log_filename)
        32 with open(log_filename, 'r') as file:
        33     print(file.read())
   
   AssertionError: 
   

[jonrkarr]

Here's an invalid RDF file for the above example: invalid.rdf