Updates to the python logging system for the AB #1011

Zoophobus · 2023-08-15T13:57:23Z

Adds a module logger that provides a logging facility for outputting messages to the standard output, the AB debug window and a file (for upload).

updating the logging system should improve stability during database importation and other multi-threaded processes (print is unsafe for threading Segmentation fault on database import #867, Excel database importer #858, partially unstable excel database importer #614)
Provides time and location stamped multiple log level messages for debugging
NOTE there is still an issue with the use of print for logging in AB dependencies (notably brightway)

Checklist

Keep pull requests small so they can be easily reviewed.
Categorize the PR by setting a good title and adding one of the labels:
bug, feature, ui, change, documentation, breaking, ci
as they show up in the changelog
Link this PR to related issues.

commits for corrections to the uncertainty distributions that were included within the same branch. Improves thread safety in logging increasing stability in the multi-threaded processes.

… to correct for use of logging over the standard console. Adds the .logs to .gitignore.

Zoophobus · 2023-08-16T08:57:16Z

Hi @marc-vdm I put you in here as this is related to one or two issues that you have had previously. These changes are based on what I have read in the PyQt documentation, regarding the use of thread safe methods (the consequence of which is to avoid the standard print function). The motivation for this was the messages from @mixib with the database import issues #614, @mixib has already tested this with a simple commenting out of the print statements, which worked (also for me) in improving the stability.

These updates are to provide a longer term solution. What I think is the most important aspect to review is the handling of files and the locations of the logs.

marc-vdm · 2023-08-16T12:52:51Z

Will do a review soon, this week for sure.

Just one question already:

updating the logging system should improve stability during database importation

NOTE there is still an issue with the use of print for logging in AB dependencies (notably brightway)

What do we do that is multithreaded during imports? I thought BW took care of importing?

Zoophobus · 2023-08-16T13:07:32Z

Brightway does perform the actual imports but with the different import types and strategies used there is input from AB. The really dumb part is that the problem is with the logging, because this has been done with the ordinary Python print() function that is not safe with threaded processes. Unfortunately, this is also the case in Brightway, so we need to raise an issue in BW to use the python logging library instead.

In line 854 in db_import_wizard of this PR there is the log statement for when linking exchanges, in Linux this contributed significantly to instabilities when using Pythons print() function (sorry for all the edits)

Zoophobus · 2023-08-16T13:19:36Z

Whoops, to answer your first question the import procedures are run from a separate thread, it is during the local imports that we use the print function to producing the logs that caused the instability

…as published on the python docs for logging), improving the stability of logging.\n2) Changes the generation of the logging object that is more compatible with pytest, supporting the existing test procedures.

coveralls · 2023-08-16T13:44:37Z

coverage: 51.801% (+0.8%) from 51.032% when pulling c5a68fd on Zoophobus:safer-threads into 30ed32c on LCA-ActivityBrowser:master.

marc-vdm · 2023-08-17T08:04:32Z

Alright thanks for the explanation!

Some more questions:

What I think is the most important aspect to review is the handling of files and the locations of the logs.

It's not entirely clear to me where the logfile is stored. Could you tell me where the files are -supposed to be?- stored? I see dir_path = os.getcwd() + "/.logs", but where does os.getcwd() normally point to on Linux and Windows? Also note that naming a folder .<anything> does not make it a hidden folder on Windows.
For me %(module)s is always logger in the terminal output and debug window. Is this supposed to be the logger class or the class writing the log? If the former, I see no use in this, if the latter, this is not working as intended.

marc-vdm

See attached comments

activity_browser/logger.py

marc-vdm · 2023-08-17T08:14:38Z

activity_browser/logger.py

+        if Logger.file_handler is None:
+            dir_path = os.getcwd() + "/.logs"
+            os.makedirs(dir_path, exist_ok=True)
+            Logger.cleanDirectory(dir_path)


Would it not be better to actually store the logfile (perhaps with sessions <timestamp> as name?) And perhaps we store the files for a year instead of a week? These files should not be larger than a few kB, so storing them forever should not even become a problem.

So you are right on these points, I've extended the period to a year. I've also provided a timestamp for the file names, although I haven't changed the stem of the name (ab_logs). This might not be required however, it might be useful to have some separation if people start going crazy with plugins

marc-vdm · 2023-08-17T08:17:36Z

activity_browser/logger.py

+            name = name + "_" + Logger.uniqueString(8) + '.log'
+            file_path = dir_path + "/" + name
+            Logger.file_handler = logging.FileHandler(file_path)
+        Logger.file_handler.setLevel(logging.WARNING)


Does this mean we only store WARNING level items in the log? I'd advocate to actually store everything, it's not really big anyway. And is there a place where I can see the different levels of logging? I'm thinking it could be useful to actually log way more detailed info to the logfile than we show in the terminal/debug -though this last sentence is a problem for later and more a new feature than it has to do with these bugs-.

So you are right, the log files generally hold a lot more than the console or window streams. I've changed the file level to include everything (well almost, it's set to DEBUG, which is lower than INFO)

So there are 4 tiers by default?
debug, info, warning and error?
That could work for us I think. We can just start writing relevant debug data to the logfiles, and perhaps in some cases provide less data to the user, as it was previously all wrapped into print of course.

Again though, this is something for later. Lets first get this working in general haha

There is a critical level, which is one level higher than an error. Plus one "lower" level, the lower level is basically a signal to turn on the turn on the logger for the dependencies too.

marc-vdm · 2023-08-17T08:23:40Z

activity_browser/bwutils/montecarlo.py

@@ -330,14 +330,14 @@ def perform_MonteCarlo_LCA(project='default', cs_name=None, iterations=10):
    mc = perform_MonteCarlo_LCA(project='ei34', cs_name='kraft paper', iterations=15)

    # test the get_results_by() method
-    print('\nTesting the get_results_by() method')
+#    print('\nTesting the get_results_by() method')


Why are all these commented?

Well for no particular reason really, I didn't put the logger here because it serves no purpose. I could just as well have left these lines the same though, I admit it doesn't make a difference

marc-vdm · 2023-08-17T08:28:24Z

activity_browser/bwutils/superstructure/file_imports.py

@@ -142,7 +143,7 @@ def database_and_key_check(data: pd.DataFrame) -> None:
                    msg = "Error in importing file with activity {} and {}".format(ds[4], ds[5])
                    raise IncompatibleDatabaseNamingError()
        except IncompatibleDatabaseNamingError as e:
-            print(msg)
+            log.error(msg)


Why is it log.error(msg) here instead of log.error(e) like here? Not saying either is right or wrong, just curious why this is the case? Would it be better to log.error("{}: {}".format(e, msg))?

Same for the 2 instances below

Part of the reason is that this error doesn't actually contain any information. The decision I made previously was to provide a statement of what caused the error when and where it happened and to raise an error that could be captured at a higher level for managing what should happen. This will be redundant when I push up the changes for scenario files soon, for the sake of doing things properly this should probably take the Exception, however for the sake of expediency I'm going to avoid this for now

activity_browser/ui/tables/models/parameters.py

activity_browser/ui/widgets/biosphere_update.py

marc-vdm · 2023-08-17T08:57:18Z

activity_browser/ui/wizards/db_import_wizard.py

@@ -108,7 +109,7 @@ def closeEvent(self, event):
        event.accept()

    def cancel_thread(self):
-        print('\nDatabase import interrupted!')
+        log.info('\nDatabase import interrupted!')


Maybe we should make this a warning?

Hmmm, this is a user initiated cause so I think it's not warranting a warning, pesonally

activity_browser/ui/wizards/uncertainty.py

Zoophobus · 2023-08-17T14:13:46Z

Alright thanks for the explanation!

Some more questions:

What I think is the most important aspect to review is the handling of files and the locations of the logs.

1. It's not entirely clear to me where the logfile is stored. Could you tell me where the files are -supposed to be?- stored? I see `            dir_path = os.getcwd() + "/.logs"`, but where does `os.getcwd()` normally point to on Linux and Windows? Also note that naming a folder `.<anything>` does not make it a hidden folder on Windows.

2. For me [`%(module)s`](https://github.com/Zoophobus/activity-browser/blob/e5e6fc79a0a1c73bca4f32a58d4a838f1dcce041/activity_browser/logger.py#L31) is always `logger` in the terminal output and debug window. Is this supposed to be the `logger` class or the class writing the log? If the former, I see no use in this, if the latter, this is not working as intended.

Hey Marc, so for the 1st point I have changed this to use the appdirs location for log files. On my distro its in –/.cache/Activity-Browser/ I'm not sure where this is in windows, before it was stupid. As for your second point, this has been quite sticky for me today, after trying too many ways to get this to work I've now resorted to using a dirty approach. I'll have a go through the python logging documentation to find a proper way to get this done, but this won't alter anything for the user. It will just be a bit cleaner from the code perspective

…le, corrects for deletion of impact assessment methods. Updates the routine to the lca_setup module for calling the logger.

…to ABHandler. The module now contains the formats and settings for the Stream handlers. Calling of the methods in the other AB modules requires passing a logging.Logger instance and the name of the calling module. These are then incorporated into the wrapping routines in the class. Additions:\n 1) An error wrapper is provided and also explicitly provides a trace of the error.\n 2) A timestamp routine is provided and used for providing the file names for log files.\n 3) A standard location based on appdirs is provided and used for log file locations.

…that improves support for trace backs. Additional changes have been made to instances calling the logger module, including in the testing suite where the calls have been updated to reflect the changed logger interface.

…ogging directory

…es a printout of the log file location.\n2) Formatting of the console streams is changed to provide a simpler, easier to read structure avoiding the time and location stamps.\n3) The extra argument from the logging module is used to pass the actual modules where the logs are created

Updates to the logging system to avoid the print statement. Merging with

e02a747

commits for corrections to the uncertainty distributions that were included within the same branch. Improves thread safety in logging increasing stability in the multi-threaded processes.

Zoophobus added bug Issues/PRs related to bugs feature Issues/PRs related to a new feature labels Aug 15, 2023

Zoophobus requested a review from marc-vdm August 15, 2023 13:57

Changes the creation of log files. Amends the uncertainty wizard test…

9fcd1f7

… to correct for use of logging over the standard console. Adds the .logs to .gitignore.

1) Simplifies the use of the python logging facility with QtThreads (…

e5e6fc7

…as published on the python docs for logging), improving the stability of logging.\n2) Changes the generation of the logging object that is more compatible with pytest, supporting the existing test procedures.

marc-vdm reviewed Aug 17, 2023

View reviewed changes

Provides an update to the Model for the calculation_setup Methods tab…

2c672b3

…le, corrects for deletion of impact assessment methods. Updates the routine to the lca_setup module for calling the logger.

Zoophobus closed this Aug 17, 2023

Zoophobus reopened this Aug 17, 2023

Zoophobus added 3 commits August 20, 2023 12:03

Corrects the author variable for creation of the Activity-Browser's l…

c5a68fd

…ogging directory

Zoophobus merged commit d6b3a9e into LCA-ActivityBrowser:master Aug 28, 2023
9 checks passed

This was referenced Sep 14, 2023

unstable excel database importer #614

Closed

Segmentation fault on database import #867

Closed

Excel database importer #858

Closed

marc-vdm mentioned this pull request Sep 22, 2023

Failed import of BW database #859

Closed

haasad mentioned this pull request Nov 14, 2023

Segmentation fault on python 3.10 when accessing sqlite database from QThread #1124

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Updates to the python logging system for the AB #1011

Updates to the python logging system for the AB #1011

Zoophobus commented Aug 15, 2023

Zoophobus commented Aug 16, 2023

marc-vdm commented Aug 16, 2023

Zoophobus commented Aug 16, 2023 •

edited

Loading

Zoophobus commented Aug 16, 2023

coveralls commented Aug 16, 2023 •

edited

Loading

marc-vdm commented Aug 17, 2023 •

edited

Loading

marc-vdm left a comment

marc-vdm Aug 17, 2023

Zoophobus Aug 17, 2023

marc-vdm Aug 17, 2023

Zoophobus Aug 17, 2023

marc-vdm Aug 18, 2023 •

edited

Loading

Zoophobus Aug 21, 2023

marc-vdm Aug 17, 2023

Zoophobus Aug 17, 2023

marc-vdm Aug 17, 2023

Zoophobus Aug 17, 2023

marc-vdm Aug 17, 2023

Zoophobus Aug 20, 2023

Zoophobus commented Aug 17, 2023

Updates to the python logging system for the AB #1011

Updates to the python logging system for the AB #1011

Conversation

Zoophobus commented Aug 15, 2023

Checklist

Zoophobus commented Aug 16, 2023

marc-vdm commented Aug 16, 2023

Zoophobus commented Aug 16, 2023 • edited Loading

Zoophobus commented Aug 16, 2023

coveralls commented Aug 16, 2023 • edited Loading

marc-vdm commented Aug 17, 2023 • edited Loading

marc-vdm left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

marc-vdm Aug 18, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Zoophobus commented Aug 17, 2023

Zoophobus commented Aug 16, 2023 •

edited

Loading

coveralls commented Aug 16, 2023 •

edited

Loading

marc-vdm commented Aug 17, 2023 •

edited

Loading

marc-vdm Aug 18, 2023 •

edited

Loading