Support logging for multiple projects, log most warnings instead of raising them #327

elfjes · 2022-07-12T07:52:05Z

This PR tackles a couple of thing with regards to logging (fixes #324):

The support for multiple (concurrent) projects means that logging also needs to support concurrent outputs/handlers. This PR implements the following
- Every project gets its own unique logger with a single filehandler outputting to the project's log file. The logger is stored under Project().logger
- The aequilibrae.context module contains a get_logger function that returns the currently active project's logger, or the global logger if there is no active project
- In most situations where a logger is needed, it is easily obtained from the given project
Whenever possible, warnings.warn calls have been replaced with the appropiate logger.warning call.
Examples have been updated
The global logger has been explicitly name global_logger to avoid confusion. The logger is still available under the old name logger for backwards compatibility
Tests are added/updated in pytest style as a proof-of-concept
- added a conftest.py that contains global fixtures
- a single global fixture has been added that is a factory to create a project (based on the siouxfalls project). Tests (and other fixtures) now only need to use this fixture and call it to create a new project
- all tests and other fixtures are still bound to a class for constistency with the current unittest style tests

Other fixes

fixed a few erroneous type hints

noteworthy points/caveats:

In order to ensure uniqueness, the project logger name now includes the full path to the project's directory. This can be a long name. In order to not clutter the log lines, the logger name has been removed from the log format for both the project loggers as the global loggers. This is a breaking change (for those users that parse the logger output, if any). We can put the name back by hardcoding it into the formatter. However, the logger name ("aequilibrae") does not add much user value, since it's kind of obvious that the logs in aequilibrae.log belong to the aequilibrae library/application
There's a catch-22 in the warning log in parameters:52. In order to log this message to the project logger, we need to know whether logging is enabled for this project, which we only know after the Parameters have been setup. I have circumvented it by logging the message to the global logger
The project loggers do not propagate their log messages to the global logger. This means that there is no single call to update the log output (for example, add a stdout handler to all loggers)

Open questions:

I'm not sure about the naming starts_logging and StartsLogging. I don't know the origin of this naming, but do you guys think it's still the right name?

aequilibrae/project/network/connector_creation.py

pedrocamargo · 2022-07-12T08:29:18Z

I am very happy for you to change the naming. This comes from a day when I had NO idea how logging worked

elfjes · 2022-07-12T08:29:49Z

I noticed I'm getting some hard errors (maybe segfaults) during tests sometimes. I initially thought it had something to do with my computer, but now I also see it popping up in CI (see linting / testing 3.7 ubuntu). Is that something you've seen before? I currently have no idea where it comes from

elfjes · 2022-07-12T08:30:58Z

I am very happy for you to change the naming. This comes from a day when I had NO idea how logging worked

Sure, will do

* renamed starts_logging and combine with log.py * moved additional setup code to __init__.py * undo falsely blackened line

pedrocamargo · 2022-07-12T09:03:14Z

I noticed I'm getting some hard errors (maybe segfaults) during tests sometimes. I initially thought it had something to do with my computer, but now I also see it popping up in CI (see linting / testing 3.7 ubuntu). Is that something you've seen before? I currently have no idea where it comes from

They were more frequent a while back, but I haven't gotten any in some time. If I remember correctly, the errors were related to errors in the Cython code that made it go outside array boundaries, which was hard to detect with the decorators that void that checking (which are in place for performance reasons).

pedrocamargo · 2022-07-12T10:16:57Z

I noticed I'm getting some hard errors (maybe segfaults) during tests sometimes. I initially thought it had something to do with my computer, but now I also see it popping up in CI (see linting / testing 3.7 ubuntu). Is that something you've seen before? I currently have no idea where it comes from

What version of Python are you using? It could be something related to dependencies (it fails for 3.7 and passes for 3.8, and the versions for SciPy and Pandas are different, for example). I wonder if this has something to do with the recent change in NumPy array sizes...

elfjes · 2022-07-12T10:48:53Z

I noticed I'm getting some hard errors (maybe segfaults) during tests sometimes. I initially thought it had something to do with my computer, but now I also see it popping up in CI (see linting / testing 3.7 ubuntu). Is that something you've seen before? I currently have no idea where it comes from

What version of Python are you using? It could be something related to dependencies (it fails for 3.7 and passes for 3.8, and the versions for SciPy and Pandas are different, for example). I wonder if this has something to do with the recent change in NumPy array sizes...

I'm running on 3.8.12 locally, but I'm not getting the error every time, and also not on the same test. It does always seem to be failing when interacting with sqlite, sometimes using sqlite directly and sometimes through pandas. Not sure what the cause is though.

aequilibrae/project/about.py

jamiecook · 2022-07-14T07:40:38Z

aequilibrae/project/network/link.py

@@ -107,12 +107,12 @@ def add_mode(self, mode: [str, Mode]):
        mode_id = self.__validate(mode)

        if mode_id in self.modes:
-            logger.warning("Mode already active for this link")
+            self._logger.warning("Mode already active for this link")


I don't think that _logger is populated for the link is it? self.project.logger perhaps?

it's a member of SafeClass, so it is there :)

jamiecook · 2022-07-14T07:41:51Z

aequilibrae/project/network/osm_downloader.py

 import time
 import re
 import requests
 from .osm_utils.osm_params import http_headers, memory
 from aequilibrae.parameters import Parameters
-from aequilibrae import logger
+from aequilibrae.context import get_logger


again - i don't think that get_logger is used here.

it's used on line 39: self.logger = logger or get_logger()

tests/aequilibrae/conftest.py

tests/aequilibrae/log/test_log.py

jamiecook · 2022-07-14T08:04:46Z

I'm also happy with this PR - a couple of questions/comments/suggestions thrown in.

The number of CI tests is pretty big at the moment - might be worth rationalising them somewhat if they are getting in the way of actually getting things shipped instead of supporting that.

elfjes · 2022-07-19T13:16:11Z

Thanks @jamiecook for your review, I've processed your changes.

I'm still looking at the SIGABRT errors, I have no idea where they come from. At my machine they popup sometimes, but only when running the full unit test suite. It seems that in CI it's pretty reproducible for python3.7 but I haven't been able to reproduce it in docker (perhaps stemming from me using python docker image instead of ubuntu).

There also shouldn't be any significant difference between this branch and develop with regards to these things. So, no solution yet...

@jamiecook what do you mean when you say the number of CI tests is pretty big? the number of workflows / matrix size of the number of unittests? If it's the number of workflows/matrix size then this could be reduced, although given that they're mostly run in parallel I'm not sure if it would speed up things. If it's about the number of unittests then I disagree, it's the unittests that make it possible to refactor code such as I did with the multiple-projects PR. I do have some ideas to speed up the tests, but that would involve making more use of pytest.

jamiecook · 2022-07-20T01:22:04Z

@elfjes - my comment was more on the number of workflows (currently 17) than the number of unittests. I agree on the utility of unittests.

However any test-suite that can't be consistently relied upon can sometimes be more of a hinderance than a help for development. Having said that I'm not sure what to do here either - python 3.7 still has a year left before EOL, so should ideally be kept. sigh

jamiecook · 2022-07-20T01:35:20Z

I've added a PR that should get rid of the first two failures from forks - #329

elfjes · 2022-07-20T06:41:40Z

I've added a PR that should get rid of the first two failures from forks - #329

Nice. I do agree that it is important to not have regularly failing pipelines (and accept such a fact). So good stuff on that PR.

However any test-suite that can't be consistently relied upon can sometimes be more of a hinderance than a help for development. Having said that I'm not sure what to do here either - python 3.7 still has a year left before EOL, so should ideally be kept. sigh

As a test I added a workflow that performs the tests in a container, which did not crash the tests. So while I still don't know what causes it exactly, it does seem to be some kind of binary incompatibility somewhere. My suggestion for now would be to run all (failing) workflows in a container when possible, which seems (n=1) to be mitigating the problem.

We may want to have a separate pr that deals with the workflows more comprehensively. There are some other gains to be made (even if we keep the same number of workflows) for example, having the unit tests depend on the linting is not necessary I'd say, and I think the test setup can also be simplified. This could be done in #329 perhaps?

jamiecook · 2022-07-20T23:34:42Z

#329 is already merged but yes a separate pr to deal with that would be better

what do you mean “ performs tests in a container” I thought all gh actions were done using containers? Or are you saying using separate containers for individual states in a workflow?

elfjes · 2022-07-21T04:42:04Z

As it turns out (and I didn't know this either), actions are performed in a virtual machine, not a container. Which makes their specific environment more difficult to predict (and reproduce). By adding a container directive to the workflow, you can perform the action in a container (inside the vm). Have a look at the test_debug.yml workflow in this PR for an example. I'll prepare a separate PR with some improvements to the ci workflows that I can think of

jamiecook · 2022-07-21T22:25:34Z

Oh yeah - that makes sense as to why each step is able to use filesystem artifacts from previous steps. I would have expected that VM would itself be a container though. Lets merge this and move discussion to your new branch - create now and mark it [WIP] if you'd like early feedback.

* Updates shapely deprecated methods (#281) * Improves performance of triggers (#278) * documentation correction (#282) * INRETS and bpr2 VD functions (#273) * French INRETS VD function First implementation of the French INRETS Volume Delay function. Beta is not used but kept for better consistancy across VD functions. * BPR2 implementation First implementation of BPR2 Volume Delay function. This doubles beta above capacity so that fewer vehicles are affected when capacity is exceeded. Double Beta insteed of using a Beta' allow to use only 2 parameters as for other VD functions. Integration into QGIS GUI is also easier * Two small changes around the edges (#288) * Closes issue #289 and adds small feature * Fixes long-standing formatting issue * fixes traffic assignment tests (#293) * Follows the Wikimedia user-agent policy (#295) * Makes sure we follow the Wikimedia user agent policy https://meta.wikimedia.org/wiki/User-Agent_policy * Adresses issue #285 (#297) * Allows for skims to be set after the creation of traffic classes * Improvement on skim saving * Updates example with change in skim saving method * Fixes typo * Fixes creation of skim matrices on multi-class assignment * Fixes final skim for travel time and introduces basic testing * Fixes example with new skimming standards * cleans tests * Relocates and Fixes path saving tests * Updates tests * QGIS adjustments (#280) * Threading * Adds connection refresh capability * Stores binaries with all tests * Makes feather optional on import * Removes repeated code * Bumps up version * Adds doc version to index * Bumps version for new release * closes issue #303 * closes issue #303 (#304) * Fixes issue 307 * Improves database structure (#310) * Improves database structure * Improves database structure * numpy 1.22 is still not the default * CI workflow to generate binaries for different NumPy versions * Sets up better tests * Sets up better tests * numpy 1.22 is still not the default * Cleans test * Run black on all source files * Adding conda_forge_recipe * Support for multiple projects (#323) * Matrix from list (#325) * Pedro/new test fix (#322) * Speeding up OSM network import * only run actions that require secrets from the Aequilbrae account. (#329) * Support logging for multiple projects, log most warnings instead of raising them (#327) * one logger per project, log most warnings instead of raising them * Multiple changes * renamed starts_logging and combine with log.py * moved additional setup code to __init__.py * undo falsely blackened line * process feedback * cleanup ci setup for unittests - do errors still occur? * Small changes to the Delaunay line creation in trying to identify consistent breaking point Co-authored-by: Danilo Ebbinghaus <91709021+daniloebbinghaus@users.noreply.github.com> Co-authored-by: Arthur Evrard <83211842+Art-Ev@users.noreply.github.com> Co-authored-by: Jan Zill <jan.zill@veitchlister.com.au> Co-authored-by: Jan <jan.christoph.zill@gmail.com> Co-authored-by: Jamie Cook <jamie.cook@veitchlister.com.au> Co-authored-by: PelleK <elfjes@users.noreply.github.com> Co-authored-by: Pelle Koster <pelle.koster@nginfra.nl> Co-authored-by: pveigadecamargo <pveigadecamargo@anl.gov>

@janzill

* Updates shapely deprecated methods (#281) * Improves performance of triggers (#278) * documentation correction (#282) * INRETS and bpr2 VD functions (#273) * French INRETS VD function First implementation of the French INRETS Volume Delay function. Beta is not used but kept for better consistancy across VD functions. * BPR2 implementation First implementation of BPR2 Volume Delay function. This doubles beta above capacity so that fewer vehicles are affected when capacity is exceeded. Double Beta instead of using a Beta' allow to use only 2 parameters as for other VD functions. Integration into QGIS GUI is also easier * Fixes styles to expose test failures * Fixes styles to expose test failures * reverts white space changes in bpr * Fixes inrets tests * Two small changes around the edges (#288) * Adds the obvious field vot to the modes table and creates and adds a script for compiling that may be useful during development * Update tests/compile.py Co-authored-by: Jamie Cook <jamie.cook@veitchlister.com.au> * Fixes import * Closes issue #289 and adds small feature * Fixes long-standing formatting issue * fixes traffic assignment tests (#293) Brilliant work, @janzill That original test was really out of whack!!! * Follows the Wikimedia user-agent policy (#295) * Makes sure we follow the Wikimedia user agent policy https://meta.wikimedia.org/wiki/User-Agent_policy * Adresses issue #285 (#297) * Allows for skims to be set after the creation of traffic classes * Improvement on skim saving * Updates example with change in skim saving method * Fixes typo * Fixes creation of skim matrices on multi-class assignment * Fixes final skim for travel time and introduces basic testing * Fixes example with new skimming standards * cleans tests * Relocates and Fixes path saving tests * Updates tests * QGIS adjustments (#280) * Threading * Adds connection refresh capability * Stores binaries with all tests * Makes feather optional on import * Removes repeated code * Bumps up version * Adds doc version to index * Bumps version for new release * closes issue #303 * closes issue #303 (#304) * Fixes issue 307 * Improves database structure (#310) * Improves database structure * Improves database structure * numpy 1.22 is still not the default * CI workflow to generate binaries for different NumPy versions * Sets up better tests * Sets up better tests * numpy 1.22 is still not the default * use temp dir * guessing this is a case problem * guessing this is a case problem * guessing this is a case problem * it was a case issue * Cleans test * Run black on all source files * Update build_linux.yml * Adding conda_forge_recipe * Support for multiple projects (#323) * Matrix from list (#325) * Pedro/new test fix (#322) * Fixes linux building * Fixes linux building * Speeding up OSM network import * only run actions that require secrets from the Aequilbrae account. (#329) * Support logging for multiple projects, log most warnings instead of raising them (#327) * one logger per project, log most warnings instead of raising them * Multiple changes * renamed starts_logging and combine with log.py * moved additional setup code to __init__.py * undo falsely blackened line * process feedback * cleanup ci setup for unittests - do errors still occur? * Edit the correct ci file * we do need more requirements * run in docker to improve isolation * apt get update Co-authored-by: Pelle Koster <pelle.koster@nginfra.nl> * Small changes to the Delaunay line creation in trying to identify consistent breaking point * Fix some warnings Co-authored-by: Pelle Koster <pelle.koster@nginfra.nl> * Refactor tests to pytest (#331) * Refactor tests * Cleanup and some comments * fix tests * process feedback * Update tests/aequilibrae/conftest.py Co-authored-by: Jamie Cook <jimi.cook@gmail.com> * rescope session-scoped fixtures inside a class to class scope to avoid confusion * fix trailing whitespace Co-authored-by: Pelle Koster <pelle.koster@nginfra.nl> Co-authored-by: Jamie Cook <jimi.cook@gmail.com> * change the check for secrets from repo_owner to has_secret (#333) * better deal with np.memmap open files (#335) Co-authored-by: Pelle <pellekoster@octagonal.nl> * Adding capability of importing and exporting networks in GMNS format (#330) * Pedro/fixes numpy changes (#342) * Fixes nan to num * Chipping along transit structure * Fixes tests * Uses new version of Numpy for Windows 3.10 only * address issues from review * unneeded Co-authored-by: pveigadecamargo <pveigadecamargo@anl.gov> Co-authored-by: Jamie Cook <jimi.cook@gmail.com> * Updates actions (#341) * Updates actions * Chipping along transit structure Co-authored-by: pveigadecamargo <pveigadecamargo@anl.gov> Co-authored-by: Jamie Cook <jamie.cook@veitchlister.com.au> * Fixes issue #344 (#345) * Fixes issue #344 Co-authored-by: François P <35044397+djfrancesco@users.noreply.github.com> * Bumps up version * Bumps up version (#346) Co-authored-by: pveigadecamargo <pveigadecamargo@anl.gov> * bug fix (#347) * Updates actions (#349) Co-authored-by: pveigadecamargo <pveigadecamargo@anl.gov> * Update Develop * stops using Kumi endpoint Co-authored-by: Danilo Ebbinghaus <91709021+daniloebbinghaus@users.noreply.github.com> Co-authored-by: Arthur Evrard <83211842+Art-Ev@users.noreply.github.com> Co-authored-by: Jan Zill <jan.zill@veitchlister.com.au> Co-authored-by: Jan <jan.christoph.zill@gmail.com> Co-authored-by: Jamie Cook <jamie.cook@veitchlister.com.au> Co-authored-by: PelleK <elfjes@users.noreply.github.com> Co-authored-by: Pelle Koster <pelle.koster@nginfra.nl> Co-authored-by: pveigadecamargo <pveigadecamargo@anl.gov> Co-authored-by: Jamie Cook <jimi.cook@gmail.com> Co-authored-by: Pelle <pellekoster@octagonal.nl>

one logger per project, log most warnings instead of raising them

a74dbf9

pedrocamargo reviewed Jul 12, 2022

View reviewed changes

aequilibrae/project/network/connector_creation.py Show resolved Hide resolved

pedrocamargo approved these changes Jul 12, 2022

View reviewed changes

elfjes mentioned this pull request Jul 12, 2022

[Suggestion] use pytest style tests (w/ fixtures etc) #326

Open

Multiple changes

eec1b93

* renamed starts_logging and combine with log.py * moved additional setup code to __init__.py * undo falsely blackened line

jamiecook reviewed Jul 14, 2022

View reviewed changes

aequilibrae/project/about.py Outdated Show resolved Hide resolved

jamiecook reviewed Jul 14, 2022

View reviewed changes

tests/aequilibrae/conftest.py Show resolved Hide resolved

jamiecook reviewed Jul 14, 2022

View reviewed changes

tests/aequilibrae/log/test_log.py Outdated Show resolved Hide resolved

process feedback

94bed0b

Pelle Koster added 5 commits July 19, 2022 17:37

cleanup ci setup for unittests - do errors still occur?

653d976

Edit the correct ci file

6fe594e

we do need more requirements

785f8d5

run in docker to improve isolation

dc8b4a8

apt get update

c148cdd

jamiecook merged commit 2e8c933 into AequilibraE:develop Jul 21, 2022

elfjes deleted the log-warnings branch July 26, 2022 07:53

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Support logging for multiple projects, log most warnings instead of raising them #327

Support logging for multiple projects, log most warnings instead of raising them #327

elfjes commented Jul 12, 2022 •

edited

Loading

pedrocamargo commented Jul 12, 2022

elfjes commented Jul 12, 2022

elfjes commented Jul 12, 2022

pedrocamargo commented Jul 12, 2022

pedrocamargo commented Jul 12, 2022 •

edited

Loading

elfjes commented Jul 12, 2022 •

edited

Loading

jamiecook Jul 14, 2022

elfjes Jul 19, 2022

jamiecook Jul 14, 2022

elfjes Jul 19, 2022

jamiecook commented Jul 14, 2022

elfjes commented Jul 19, 2022

jamiecook commented Jul 20, 2022

jamiecook commented Jul 20, 2022

elfjes commented Jul 20, 2022

jamiecook commented Jul 20, 2022

elfjes commented Jul 21, 2022

jamiecook commented Jul 21, 2022

Support logging for multiple projects, log most warnings instead of raising them #327

Support logging for multiple projects, log most warnings instead of raising them #327

Conversation

elfjes commented Jul 12, 2022 • edited Loading

pedrocamargo commented Jul 12, 2022

elfjes commented Jul 12, 2022

elfjes commented Jul 12, 2022

pedrocamargo commented Jul 12, 2022

pedrocamargo commented Jul 12, 2022 • edited Loading

elfjes commented Jul 12, 2022 • edited Loading

jamiecook Jul 14, 2022

Choose a reason for hiding this comment

elfjes Jul 19, 2022

Choose a reason for hiding this comment

jamiecook Jul 14, 2022

Choose a reason for hiding this comment

elfjes Jul 19, 2022

Choose a reason for hiding this comment

jamiecook commented Jul 14, 2022

elfjes commented Jul 19, 2022

jamiecook commented Jul 20, 2022

jamiecook commented Jul 20, 2022

elfjes commented Jul 20, 2022

jamiecook commented Jul 20, 2022

elfjes commented Jul 21, 2022

jamiecook commented Jul 21, 2022

elfjes commented Jul 12, 2022 •

edited

Loading

pedrocamargo commented Jul 12, 2022 •

edited

Loading

elfjes commented Jul 12, 2022 •

edited

Loading